[2024-05-28T08:11:57.995562Z] [info] +++ setup notes +++
[2024-05-28T08:11:57.995966Z] [info] Running on openqaworker21:30 (Linux 5.14.21-150500.55.65-default #1 SMP PREEMPT_DYNAMIC Thu May 23 04:57:11 UTC 2024 (a46829d) x86_64)
[2024-05-28T08:11:58.003165Z] [debug] Found ASSET_1, caching Tumbleweed.x86_64-1.0-libvirt-Snapshot20240527.vagrant.libvirt.box
[2024-05-28T08:11:58.005920Z] [info] Downloading Tumbleweed.x86_64-1.0-libvirt-Snapshot20240527.vagrant.libvirt.box, request #213614 sent to Cache Service
[2024-05-28T08:12:08.116864Z] [info] Download of Tumbleweed.x86_64-1.0-libvirt-Snapshot20240527.vagrant.libvirt.box processed:
[info] [#213614] Cache size of "/var/lib/openqa/cache" is 398 GiB, with limit 400 GiB
[info] [#213614] Downloading "Tumbleweed.x86_64-1.0-libvirt-Snapshot20240527.vagrant.libvirt.box" from "https://openqa.opensuse.org/tests/4227521/asset/other/Tumbleweed.x86_64-1.0-libvirt-Snapshot20240527.vagrant.libvirt.box"
[info] [#213614] Content of "/var/lib/openqa/cache/openqa.opensuse.org/Tumbleweed.x86_64-1.0-libvirt-Snapshot20240527.vagrant.libvirt.box" has not changed, updating last use

[2024-05-28T08:12:08.118938Z] [debug] Found ASSET_2, caching Tumbleweed.x86_64-1.0-virtualbox-Snapshot20240527.vagrant.virtualbox.box
[2024-05-28T08:12:08.121555Z] [info] Downloading Tumbleweed.x86_64-1.0-virtualbox-Snapshot20240527.vagrant.virtualbox.box, request #213615 sent to Cache Service
[2024-05-28T08:12:18.227983Z] [info] Download of Tumbleweed.x86_64-1.0-virtualbox-Snapshot20240527.vagrant.virtualbox.box processed:
[info] [#213615] Cache size of "/var/lib/openqa/cache" is 398 GiB, with limit 400 GiB
[info] [#213615] Downloading "Tumbleweed.x86_64-1.0-virtualbox-Snapshot20240527.vagrant.virtualbox.box" from "https://openqa.opensuse.org/tests/4227521/asset/other/Tumbleweed.x86_64-1.0-virtualbox-Snapshot20240527.vagrant.virtualbox.box"
[info] [#213615] Content of "/var/lib/openqa/cache/openqa.opensuse.org/Tumbleweed.x86_64-1.0-virtualbox-Snapshot20240527.vagrant.virtualbox.box" has not changed, updating last use

[2024-05-28T08:12:18.229931Z] [debug] Found ASSET_256, caching openSUSE-Tumbleweed-DVD-x86_64-Snapshot20240527-Media.iso.sha256
[2024-05-28T08:12:18.232298Z] [info] Downloading openSUSE-Tumbleweed-DVD-x86_64-Snapshot20240527-Media.iso.sha256, request #213616 sent to Cache Service
[2024-05-28T08:12:28.359572Z] [info] Download of openSUSE-Tumbleweed-DVD-x86_64-Snapshot20240527-Media.iso.sha256 processed:
[info] [#213616] Cache size of "/var/lib/openqa/cache" is 398 GiB, with limit 400 GiB
[info] [#213616] Downloading "openSUSE-Tumbleweed-DVD-x86_64-Snapshot20240527-Media.iso.sha256" from "https://openqa.opensuse.org/tests/4227521/asset/other/openSUSE-Tumbleweed-DVD-x86_64-Snapshot20240527-Media.iso.sha256"
[info] [#213616] Content of "/var/lib/openqa/cache/openqa.opensuse.org/openSUSE-Tumbleweed-DVD-x86_64-Snapshot20240527-Media.iso.sha256" has not changed, updating last use

[2024-05-28T08:12:28.361751Z] [debug] Found ISO, caching openSUSE-Tumbleweed-DVD-x86_64-Snapshot20240527-Media.iso
[2024-05-28T08:12:28.364342Z] [info] Downloading openSUSE-Tumbleweed-DVD-x86_64-Snapshot20240527-Media.iso, request #213617 sent to Cache Service
[2024-05-28T08:12:38.464931Z] [info] Download of openSUSE-Tumbleweed-DVD-x86_64-Snapshot20240527-Media.iso processed:
[info] [#213617] Cache size of "/var/lib/openqa/cache" is 398 GiB, with limit 400 GiB
[info] [#213617] Downloading "openSUSE-Tumbleweed-DVD-x86_64-Snapshot20240527-Media.iso" from "https://openqa.opensuse.org/tests/4227521/asset/iso/openSUSE-Tumbleweed-DVD-x86_64-Snapshot20240527-Media.iso"
[info] [#213617] Content of "/var/lib/openqa/cache/openqa.opensuse.org/openSUSE-Tumbleweed-DVD-x86_64-Snapshot20240527-Media.iso" has not changed, updating last use

[2024-05-28T08:12:38.467679Z] [info] Rsync from 'rsync://openqa.opensuse.org/tests' to '/var/lib/openqa/cache/openqa.opensuse.org', request #213619 sent to Cache Service
[2024-05-28T08:12:48.600468Z] [info] Output of rsync:
[info] [#213619] Calling: rsync -avHP --timeout 1800 rsync://openqa.opensuse.org/tests/ --delete /var/lib/openqa/cache/openqa.opensuse.org/tests/
Try 1:
receiving incremental file list
obs/.git/
obs/.git/FETCH_HEAD

              0   0%    0.00kB/s    0:00:00  
            483 100%  471.68kB/s    0:00:00 (xfr#1, ir-chk=1158/1178)
obs/.git/index

              0   0%    0.00kB/s    0:00:00  
          2,745 100%    2.62MB/s    0:00:00 (xfr#2, ir-chk=1153/1178)
obs/.git/logs/HEAD

              0   0%    0.00kB/s    0:00:00  
    393,512,704  63%  375.28MB/s    0:00:00  
    616,949,025 100%  375.95MB/s    0:00:01 (xfr#3, ir-chk=1133/1178)
obs/.git/objects/
obs/.git/refs/heads/
openqa/.git/
openqa/.git/FETCH_HEAD

              0   0%    0.00kB/s    0:00:00  
            554 100%    0.65kB/s    0:00:00 (xfr#4, ir-chk=1167/1450)
openqa/.git/index

              0   0%    0.00kB/s    0:00:00  
          3,093 100%    3.64kB/s    0:00:00 (xfr#5, ir-chk=1162/1450)
openqa/.git/logs/HEAD

              0   0%    0.00kB/s    0:00:00  
     10,404,223 100%   11.58MB/s    0:00:00 (xfr#6, ir-chk=1140/1450)
openqa/.git/objects/
openqa/.git/refs/heads/
openqa/products/openqa/needles/.git/
openqa/products/openqa/needles/.git/FETCH_HEAD

              0   0%    0.00kB/s    0:00:00  
            259 100%    0.29kB/s    0:00:00 (xfr#7, ir-chk=1019/1609)
openqa/products/openqa/needles/.git/index

              0   0%    0.00kB/s    0:00:00  
         22,443 100%   25.46kB/s    0:00:00 (xfr#8, ir-chk=1014/1609)
openqa/products/openqa/needles/.git/logs/HEAD

              0   0%    0.00kB/s    0:00:00  
     20,799,665 100%   21.68MB/s    0:00:00 (xfr#9, ir-chk=1002/1619)
openqa/products/openqa/needles/.git/objects/
openqa/products/openqa/needles/.git/refs/heads/
opensuse/.git/
opensuse/.git/FETCH_HEAD

              0   0%    0.00kB/s    0:00:00  
          7,264 100%    7.69kB/s    0:00:00 (xfr#10, ir-chk=1012/1698)
opensuse/.git/index

              0   0%    0.00kB/s    0:00:00  
        636,809 100%  673.03kB/s    0:00:00 (xfr#11, ir-chk=1007/1698)
opensuse/.git/logs/HEAD

              0   0%    0.00kB/s    0:00:00  
     28,680,836 100%   27.38MB/s    0:00:00 (xfr#12, ir-chk=1007/1717)
opensuse/.git/objects/
opensuse/.git/refs/heads/
opensuse/products/opensuse/needles/.git/
opensuse/products/opensuse/needles/.git/FETCH_HEAD

              0   0%    0.00kB/s    0:00:00  
            700  86%    0.51kB/s    0:00:00  
            810 100%    0.59kB/s    0:00:01 (xfr#13, ir-chk=1014/21425)
opensuse/products/opensuse/needles/.git/index

              0   0%    0.00kB/s    0:00:00  
      1,574,039 100%  300.22MB/s    0:00:00 (xfr#14, ir-chk=1009/21425)
opensuse/products/opensuse/needles/.git/logs/HEAD

              0   0%    0.00kB/s    0:00:00  
    130,888,739 100%  126.21MB/s    0:00:00 (xfr#15, ir-chk=1009/21444)
opensuse/products/opensuse/needles/.git/objects/
opensuse/products/opensuse/needles/.git/refs/heads/

sent 347,764 bytes  received 1,402,450 bytes  269,263.69 bytes/sec
total size is 5,860,321,464  speedup is 3,348.35


[2024-05-28T08:12:48.600592Z] [info] Finished to rsync tests
[2024-05-28T08:12:48.606034Z] [debug] +++ worker notes +++
[37m[2024-05-28T08:12:48.942940Z] [debug] [pid:2742] Current version is 4.6.1716387241.58dd214 [interface v40][0m
[37m[2024-05-28T08:12:48.954912Z] [debug] [pid:2742] git hash in 'opensuse': 3dbc24737e1819361e511023588461e801dd10e9[0m
[37m[2024-05-28T08:12:48.971427Z] [debug] [pid:2742] git url in 'opensuse': https://github.com/os-autoinst/os-autoinst-distri-opensuse.git[0m
[37m[2024-05-28T08:12:49.286391Z] [debug] [pid:2742] usingenv DESKTOP=gnome[0m
[37m[2024-05-28T08:12:49.286574Z] [debug] [pid:2742] usingenv DISTRI=opensuse[0m
[37m[2024-05-28T08:12:49.286663Z] [debug] [pid:2742] usingenv QEMUCPU=host[0m
[37m[2024-05-28T08:12:49.286745Z] [debug] [pid:2742] usingenv INSTLANG=en_US[0m
[37m[2024-05-28T08:12:49.286823Z] [debug] [pid:2742] usingenv DVD=1[0m
[37m[2024-05-28T08:12:49.286893Z] [debug] [pid:2742] usingenv GNOME=1[0m
[37m[2024-05-28T08:12:49.286973Z] [debug] [pid:2742] usingenv ISO=openSUSE-Tumbleweed-DVD-x86_64-Snapshot20240527-Media.iso[0m
[37m[2024-05-28T08:12:49.287057Z] [debug] [pid:2742] usingenv ISO_MAXSIZE=4700372992[0m
[37m[2024-05-28T08:12:49.302971Z] [debug] [pid:2742] parse_vars (variables parsed from YAML schedule):[0m
[37m[2024-05-28T08:12:49.303574Z] [debug] [pid:2742] ---
  DESKTOP: gnome
  NUMDISKS: '4'
  ENCRYPT: 1
  [0m
[37m[2024-05-28T08:12:49.304076Z] [debug] [pid:2742] ---
  - autoyast/prepare_profile
  - installation/bootloader_start
  - autoyast/installation
  - installation/boot_encrypt
  - installation/first_boot
  - autoyast/console
  - autoyast/clone
  - console/validate_multi_btrfs_partitioning
  - console/validate_encrypt
  - autoyast/verify_cloned_profile
  [0m
[37m[2024-05-28T08:12:49.304536Z] [debug] [pid:2742] parse_test_suite_data (data parsed from YAML test_data):[0m
[37m[2024-05-28T08:12:49.310338Z] [debug] [pid:2742] ---
  cryptsetup:
    device_status:
      message: is active and is in use.
      properties:
        type: LUKS1
        cipher: aes-xts-plain64
        device: /dev/vdd1
        key_location: dm-crypt
        mode: read/write
  crypttab:
    num_devices_encrypted: 1
  backup_path: /root/bkp_luks_header
  backup_file_info: LUKS encrypted file, ver 1 \[aes, xts-plain64, sha256\]
  multi_devices:
  - mount_point: /
    label: root_multi_btrfs
    devices:
    - /dev/vda2
    - /dev/vdb1
  - mount_point: /test
    label: test_multi_btrfs
    devices:
    - /dev/vdc
    - /dev/mapper/cr_test
  profile:
    partitioning:
      drive:
      - device: /dev/vda
        disklabel: gpt
        partitions:
          __count: 3
          partition:
          - filesystem: swap
            mount: swap
        type: CT_DISK
      - device: /dev/vdb
        disklabel: gpt
        partitions:
          __count: 1
          partition:
            partition_nr: 1
        type: CT_DISK
      - device: /dev/vdc
        disklabel: none
        partitions:
          __count: 1
          partition:
            create: 'false'
        type: CT_DISK
      - device: /dev/vdd
        disklabel: gpt
        partitions:
          __count: 1
          partition:
            crypt_method: luks1
        type: CT_DISK
      - label:
          _descendant: any
          __text: root_multi_btrfs
        btrfs_options:
          data_raid_level: raid0
          metadata_raid_level: raid1
        disklabel: none
        enable_snapshots: 'false'
        partitions:
          partition:
          - filesystem: btrfs
            label: root_multi_btrfs
            mount: /
            subvolumes:
              subvolume:
              - copy_on_write: 'true'
                path: tmp
              - copy_on_write: 'true'
                path: usr/local
              - copy_on_write: 'true'
                path: home
              - copy_on_write: 'true'
                path: root
              - copy_on_write: 'true'
                path: srv
              - copy_on_write: 'false'
                path: var
              - copy_on_write: 'true'
                path: opt
            subvolumes_prefix: '@'
        type: CT_BTRFS
      - label:
          _descendant: any
          __text: test_multi_btrfs
        btrfs_options:
          data_raid_level: raid0
          metadata_raid_level: raid1
        disklabel: none
        partitions:
          partition:
          - filesystem: btrfs
            label: test_multi_btrfs
            mount: /test
            subvolumes_prefix: ''
        type: CT_BTRFS
  [0m
[37m[2024-05-28T08:12:49.314295Z] [debug] [pid:2742] scheduling prepare_profile tests/autoyast/prepare_profile.pm[0m
[37m[2024-05-28T08:12:49.331639Z] [debug] [pid:2742] scheduling bootloader_start tests/installation/bootloader_start.pm[0m
[37m[2024-05-28T08:12:49.334201Z] [debug] [pid:2742] scheduling installation tests/autoyast/installation.pm[0m
[37m[2024-05-28T08:12:49.334736Z] [debug] [pid:2742] scheduling boot_encrypt tests/installation/boot_encrypt.pm[0m
[37m[2024-05-28T08:12:49.335558Z] [debug] [pid:2742] scheduling first_boot tests/installation/first_boot.pm[0m
[37m[2024-05-28T08:12:49.336111Z] [debug] [pid:2742] scheduling console tests/autoyast/console.pm[0m
[37m[2024-05-28T08:12:49.336658Z] [debug] [pid:2742] scheduling clone tests/autoyast/clone.pm[0m
[37m[2024-05-28T08:12:49.337419Z] [debug] [pid:2742] scheduling validate_multi_btrfs_partitioning tests/console/validate_multi_btrfs_partitioning.pm[0m
[37m[2024-05-28T08:12:49.338008Z] [debug] [pid:2742] scheduling validate_encrypt tests/console/validate_encrypt.pm[0m
[37m[2024-05-28T08:12:49.338521Z] [debug] [pid:2742] scheduling verify_cloned_profile tests/autoyast/verify_cloned_profile.pm[0m
[2024-05-28T08:12:49.346685Z] [info] [pid:2752] cmdsrv: daemon reachable under http://*:20303/BNGyhHHiGaVcXGrV/
[2024-05-28T08:12:49.348336Z] [info] [pid:2752] Listening at "http://[::]:20303"
Web application available at http://[::]:20303
[37m[2024-05-28T08:12:49.353157Z] [debug] [pid:2742] git hash in 'opensuse/products/opensuse/needles': 9c264ee66e0366e6bfd7b2a1d219ca52ddb44beb[0m
[37m[2024-05-28T08:12:49.374092Z] [debug] [pid:2742] git url in 'opensuse/products/opensuse/needles': git@github.com:os-autoinst/os-autoinst-needles-opensuse.git[0m
[37m[2024-05-28T08:12:49.374264Z] [debug] [pid:2742] init needles from opensuse/products/opensuse/needles[0m
[37m[2024-05-28T08:12:50.041168Z] [debug] [pid:2742] loaded 7144 needles[0m
[37m[2024-05-28T08:12:50.170114Z] [debug] [pid:2742] 2742: channel_out 16, channel_in 15[0m
[37m[2024-05-28T08:12:50.222163Z] [debug] [pid:3081] 3081: cmdpipe 14, rsppipe 17[0m
[37m[2024-05-28T08:12:50.222438Z] [debug] [pid:3081] started mgmt loop with pid 3081[0m
[37m[2024-05-28T08:12:50.280548Z] [debug] [pid:3081] Launching external video encoder: ffmpeg -y -hide_banner -nostats -r 24 -f image2pipe -vcodec ppm -i - -pix_fmt yuv420p -c:v libvpx-vp9 -crf 35 -b:v 1500k -cpu-used 1 'video.webm'[0m
[37m[2024-05-28T08:12:50.350873Z] [debug] [pid:3081] qemu version detected: 7.1.0[0m
[37m[2024-05-28T08:12:50.352658Z] [debug] [pid:3081] running `/usr/bin/chattr +C /var/lib/openqa/pool/30/raid`[0m
[37m[2024-05-28T08:12:50.368561Z] [debug] [pid:3081] Command `/usr/bin/chattr +C /var/lib/openqa/pool/30/raid` terminated with 1
  /usr/bin/chattr: Operation not supported while setting flags on /var/lib/openqa/pool/30/raid[0m
[37m[2024-05-28T08:12:50.368662Z] [debug] [pid:3081] Configuring storage controllers and block devices[0m
[37m[2024-05-28T08:12:50.369443Z] [debug] [pid:3081] running `/usr/bin/qemu-img info --output=json /var/lib/openqa/pool/30/openSUSE-Tumbleweed-DVD-x86_64-Snapshot20240527-Media.iso`[0m
[37m[2024-05-28T08:12:50.413242Z] [debug] [pid:3081] Initializing block device images[0m
[37m[2024-05-28T08:12:50.413511Z] [debug] [pid:3081] running `/usr/bin/qemu-img create -f qcow2 /var/lib/openqa/pool/30/raid/hd0 20G`[0m
[37m[2024-05-28T08:12:50.452412Z] [debug] [pid:3081] Formatting '/var/lib/openqa/pool/30/raid/hd0', fmt=qcow2 cluster_size=65536 extended_l2=off compression_type=zlib size=21474836480 lazy_refcounts=off refcount_bits=16[0m
[37m[2024-05-28T08:12:50.452511Z] [debug] [pid:3081] running `/usr/bin/qemu-img create -f qcow2 /var/lib/openqa/pool/30/raid/hd1 20G`[0m
[37m[2024-05-28T08:12:50.487445Z] [debug] [pid:3081] Formatting '/var/lib/openqa/pool/30/raid/hd1', fmt=qcow2 cluster_size=65536 extended_l2=off compression_type=zlib size=21474836480 lazy_refcounts=off refcount_bits=16[0m
[37m[2024-05-28T08:12:50.487537Z] [debug] [pid:3081] running `/usr/bin/qemu-img create -f qcow2 /var/lib/openqa/pool/30/raid/hd2 20G`[0m
[37m[2024-05-28T08:12:50.523992Z] [debug] [pid:3081] Formatting '/var/lib/openqa/pool/30/raid/hd2', fmt=qcow2 cluster_size=65536 extended_l2=off compression_type=zlib size=21474836480 lazy_refcounts=off refcount_bits=16[0m
[37m[2024-05-28T08:12:50.524089Z] [debug] [pid:3081] running `/usr/bin/qemu-img create -f qcow2 /var/lib/openqa/pool/30/raid/hd3 20G`[0m
[37m[2024-05-28T08:12:50.560785Z] [debug] [pid:3081] Formatting '/var/lib/openqa/pool/30/raid/hd3', fmt=qcow2 cluster_size=65536 extended_l2=off compression_type=zlib size=21474836480 lazy_refcounts=off refcount_bits=16[0m
[37m[2024-05-28T08:12:50.560866Z] [debug] [pid:3081] running `/usr/bin/qemu-img create -f qcow2 -F raw -b /var/lib/openqa/pool/30/openSUSE-Tumbleweed-DVD-x86_64-Snapshot20240527-Media.iso /var/lib/openqa/pool/30/raid/cd0-overlay0 4497342464`[0m
[37m[2024-05-28T08:12:50.598574Z] [debug] [pid:3081] Formatting '/var/lib/openqa/pool/30/raid/cd0-overlay0', fmt=qcow2 cluster_size=65536 extended_l2=off compression_type=zlib size=4497342464 backing_file=/var/lib/openqa/pool/30/openSUSE-Tumbleweed-DVD-x86_64-Snapshot20240527-Media.iso backing_fmt=raw lazy_refcounts=off refcount_bits=16[0m
[37m[2024-05-28T08:12:50.598653Z] [debug] [pid:3081] init_blockdev_images: Finished creating block devices[0m
[37m[2024-05-28T08:12:50.599643Z] [debug] [pid:3081] starting: /usr/bin/qemu-system-x86_64 -device VGA,edid=on,xres=1024,yres=768 -only-migratable -chardev ringbuf,id=serial0,logfile=serial0,logappend=on -serial chardev:serial0 -audiodev none,id=snd0 -device intel-hda -device hda-output,audiodev=snd0 -global isa-fdc.fdtypeA=none -m 1536 -cpu host -netdev user,id=qanet0 -device virtio-net,netdev=qanet0,mac=52:54:00:12:34:56 -object rng-random,filename=/dev/urandom,id=rng0 -device virtio-rng-pci,rng=rng0 -boot once=d -device qemu-xhci -device usb-tablet -smp 1 -enable-kvm -no-shutdown -vnc :120,share=force-shared -device virtio-serial -chardev pipe,id=virtio_console,path=virtio_console,logfile=virtio_console.log,logappend=on -device virtconsole,chardev=virtio_console,name=org.openqa.console.virtio_console -chardev pipe,id=virtio_console_user,path=virtio_console_user,logfile=virtio_console_user.log,logappend=on -device virtconsole,chardev=virtio_console_user,name=org.openqa.console.virtio_console_user -chardev socket,path=qmp_socket,server=on,wait=off,id=qmp_socket,logfile=qmp_socket.log,logappend=on -qmp chardev:qmp_socket -S -device virtio-scsi-pci,id=scsi0 -blockdev driver=file,node-name=hd0-file,filename=/var/lib/openqa/pool/30/raid/hd0,cache.no-flush=on -blockdev driver=qcow2,node-name=hd0,file=hd0-file,cache.no-flush=on,discard=unmap -device virtio-blk,id=hd0-device,drive=hd0,serial=hd0 -blockdev driver=file,node-name=hd1-file,filename=/var/lib/openqa/pool/30/raid/hd1,cache.no-flush=on -blockdev driver=qcow2,node-name=hd1,file=hd1-file,cache.no-flush=on,discard=unmap -device virtio-blk,id=hd1-device,drive=hd1,serial=hd1 -blockdev driver=file,node-name=hd2-file,filename=/var/lib/openqa/pool/30/raid/hd2,cache.no-flush=on -blockdev driver=qcow2,node-name=hd2,file=hd2-file,cache.no-flush=on,discard=unmap -device virtio-blk,id=hd2-device,drive=hd2,serial=hd2 -blockdev driver=file,node-name=hd3-file,filename=/var/lib/openqa/pool/30/raid/hd3,cache.no-flush=on -blockdev driver=qcow2,node-name=hd3,file=hd3-file,cache.no-flush=on,discard=unmap -device virtio-blk,id=hd3-device,drive=hd3,serial=hd3 -blockdev driver=file,node-name=cd0-overlay0-file,filename=/var/lib/openqa/pool/30/raid/cd0-overlay0,cache.no-flush=on -blockdev driver=qcow2,node-name=cd0-overlay0,file=cd0-overlay0-file,cache.no-flush=on,discard=unmap -device scsi-cd,id=cd0-device,drive=cd0-overlay0,serial=cd0[0m
[37m[2024-05-28T08:12:50.605538Z] [debug] [pid:3081] Waiting for 0 attempts[0m
[37m[2024-05-28T08:12:51.606081Z] [debug] [pid:3081] Waiting for 1 attempts[0m
[37m[2024-05-28T08:12:52.606531Z] [debug] [pid:3081] Finished after 2 attempts[0m
[37m[2024-05-28T08:12:52.619677Z] [debug] [pid:3081] Establishing VNC connection to localhost:6020[0m
[37m[2024-05-28T08:12:52.622047Z] [debug] [pid:3081] pointer type 0 0 640 480 -257[0m
[37m[2024-05-28T08:12:52.622117Z] [debug] [pid:3081] led state 0 1 1 -261[0m
[37m[2024-05-28T08:12:52.678885Z] [debug] [pid:3081] Start CPU[0m
[37m[2024-05-28T08:12:52.679211Z] [debug] [pid:3081] EVENT {"data":{"client":{"family":"ipv4","host":"127.0.0.1","service":"53856","websocket":false},"server":{"auth":"none","family":"ipv4","host":"0.0.0.0","service":"6020","websocket":false}},"event":"VNC_CONNECTED","timestamp":{"microseconds":620224,"seconds":1716883972}}[0m
[37m[2024-05-28T08:12:52.679376Z] [debug] [pid:3081] EVENT {"data":{"client":{"family":"ipv4","host":"127.0.0.1","service":"53856","websocket":false},"server":{"auth":"none","family":"ipv4","host":"0.0.0.0","service":"6020","websocket":false}},"event":"VNC_INITIALIZED","timestamp":{"microseconds":621239,"seconds":1716883972}}[0m
[37m[2024-05-28T08:12:52.679549Z] [debug] [pid:3081] EVENT {"event":"RESUME","timestamp":{"microseconds":679294,"seconds":1716883972}}[0m
GOT GO

[37m[2024-05-28T08:12:52.686282Z] [debug] [pid:3081] QEMU: QEMU emulator version 7.1.0 (SUSE Linux Enterprise 15)[0m
[37m[2024-05-28T08:12:52.686333Z] [debug] [pid:3081] QEMU: Copyright (c) 2003-2022 Fabrice Bellard and the QEMU Project developers[0m
[37m[2024-05-28T08:12:52.688288Z] [debug] [pid:2759] Snapshots are supported[0m
[1;34m[2024-05-28T08:12:52.689356Z] [debug] [pid:2759] ||| starting prepare_profile tests/autoyast/prepare_profile.pm[0m
[2024-05-28T08:12:52.690530Z] [debug] [pid:2759] tests/autoyast/prepare_profile.pm:22 called testapi::get_test_data
[2024-05-28T08:12:52.690728Z] [debug] [pid:2759] <<< testapi::get_test_data(path="opensuse/data/autoyast_opensuse/autoyast_multi_btrfs.xml")
[2024-05-28T08:12:52.691893Z] [debug] [pid:2759] tests/autoyast/prepare_profile.pm:27 called autoyast::prepare_ay_file -> lib/autoyast.pm:859 called testapi::get_test_data
[2024-05-28T08:12:52.691972Z] [debug] [pid:2759] <<< testapi::get_test_data(path="opensuse/data/autoyast_opensuse/autoyast_multi_btrfs.xml")
[2024-05-28T08:12:52.692352Z] [debug] [pid:2759] tests/autoyast/prepare_profile.pm:27 called autoyast::prepare_ay_file -> lib/autoyast.pm:874 called autoyast::upload_profile -> lib/autoyast.pm:742 called testapi::save_tmp_file
[2024-05-28T08:12:52.692426Z] [debug] [pid:2759] <<< testapi::save_tmp_file(path="autoyast_opensuse/autoyast_multi_btrfs.xml")
[1;34m[2024-05-28T08:12:52.694656Z] [debug] [pid:2759] ||| finished prepare_profile autoyast (runtime: 0 s)[0m
[1;34m[2024-05-28T08:12:52.755318Z] [debug] [pid:2759] ||| starting bootloader_start tests/installation/bootloader_start.pm[0m
[2024-05-28T08:12:52.755911Z] [debug] [pid:2759] tests/installation/bootloader_start.pm:83 called testapi::record_info
[2024-05-28T08:12:52.756020Z] [debug] [pid:2759] <<< testapi::record_info(title="bootloader", output="", result="ok")
[2024-05-28T08:12:52.756265Z] [debug] [pid:2759] tests/installation/bootloader_start.pm:84 called bootloader::run -> tests/installation/bootloader.pm:43 called bootloader_setup::select_bootmenu_option -> lib/bootloader_setup.pm:330 called testapi::assert_screen
[2024-05-28T08:12:52.756336Z] [debug] [pid:2759] <<< testapi::assert_screen(mustmatch="inst-bootmenu", timeout=30)
[37m[2024-05-28T08:12:53.824921Z] [debug] [pid:3081] no match: 29.0s, best candidate: bootloader-grub2-alp-selfinstall-20230327 (0.00)[0m
Input #0, image2pipe, from 'pipe:':
  Duration: N/A, bitrate: N/A
  Stream #0:0: Video: ppm, rgb24, 1024x768, 24 fps, 24 tbr, 24 tbn, 24 tbc
Stream mapping:
  Stream #0:0 -> #0:0 (ppm (native) -> vp9 (libvpx-vp9))
[libvpx-vp9 @ 0x55b657a04900] v1.11.0
Output #0, webm, to 'video.webm':
  Metadata:
    encoder         : Lavf58.76.100
  Stream #0:0: Video: vp9, yuv420p(tv, progressive), 1024x768, q=2-31, 1500 kb/s, 24 fps, 1k tbn
    Metadata:
      encoder         : Lavc58.134.100 libvpx-vp9
    Side data:
      cpb: bitrate max/min/avg: 0/0/0 buffer size: 0 vbv_delay: N/A
[37m[2024-05-28T08:12:54.741590Z] [debug] [pid:3081] no match: 28.0s, best candidate: bootloader-grub2-alp-selfinstall-20230327 (0.00)[0m
[32m[2024-05-28T08:12:55.799183Z] [debug] [pid:2759] >>> testapi::_handle_found_needle: found bootmenu-Slowroll-20240109, similarity 1.00 @ 0/0[0m
[2024-05-28T08:12:55.800207Z] [debug] [pid:2759] tests/installation/bootloader_start.pm:84 called bootloader::run -> tests/installation/bootloader.pm:43 called bootloader_setup::select_bootmenu_option -> lib/bootloader_setup.pm:348 called testapi::send_key_until_needlematch
[2024-05-28T08:12:55.800325Z] [debug] [pid:2759] <<< testapi::check_screen(mustmatch="inst-oninstallation", timeout=0)
[37m[2024-05-28T08:12:57.022476Z] [debug] [pid:3081] no match: -0.9s, best candidate: inst-oninstallation-20191209 (0.45)[0m
[32m[2024-05-28T08:12:57.094446Z] [debug] [pid:2759] >>> testapi::_check_backend_response: match=inst-oninstallation timed out after 0 (check_screen)[0m
[2024-05-28T08:12:57.109799Z] [debug] [pid:2759] tests/installation/bootloader_start.pm:84 called bootloader::run -> tests/installation/bootloader.pm:43 called bootloader_setup::select_bootmenu_option -> lib/bootloader_setup.pm:348 called testapi::send_key_until_needlematch
[2024-05-28T08:12:57.109911Z] [debug] [pid:2759] <<< testapi::wait_screen_change(timeout=10, similarity_level=50)
[2024-05-28T08:12:57.110647Z] [debug] [pid:2759] tests/installation/bootloader_start.pm:84 called bootloader::run -> tests/installation/bootloader.pm:43 called bootloader_setup::select_bootmenu_option -> lib/bootloader_setup.pm:348 called testapi::send_key_until_needlematch
[2024-05-28T08:12:57.110725Z] [debug] [pid:2759] <<< testapi::send_key(key="down", wait_screen_change=0)
[32m[2024-05-28T08:12:57.558633Z] [debug] [pid:2759] >>> testapi::wait_screen_change: screen change seen after 0.17379093170166 seconds (similarity: 25.510891502542)[0m
[2024-05-28T08:12:57.558921Z] [debug] [pid:2759] tests/installation/bootloader_start.pm:84 called bootloader::run -> tests/installation/bootloader.pm:43 called bootloader_setup::select_bootmenu_option -> lib/bootloader_setup.pm:348 called testapi::send_key_until_needlematch
[2024-05-28T08:12:57.559095Z] [debug] [pid:2759] <<< testapi::check_screen(mustmatch="inst-oninstallation", timeout=5)
[32m[2024-05-28T08:12:57.759685Z] [debug] [pid:2759] >>> testapi::_handle_found_needle: found inst-oninstallation-20191209, similarity 1.00 @ 246/192[0m
[2024-05-28T08:12:57.760241Z] [debug] [pid:2759] tests/installation/bootloader_start.pm:84 called bootloader::run -> tests/installation/bootloader.pm:53 called bootloader_setup::bootmenu_default_params -> lib/bootloader_setup.pm:623 called bootloader_setup::type_boot_parameters -> lib/bootloader_setup.pm:1592 called testapi::type_string
[2024-05-28T08:12:57.760409Z] [debug] [pid:2759] <<< testapi::type_string(string="  Y2DEBUG=1 vga=791 video=1024x768 plymouth.ignore-serial-consoles console=ttyS0 console=tty linuxrc.log=/dev/ttyS0 linuxrc.core=/dev/ttyS0 linuxrc.debug=4,trace reboot_timeout=0  ", max_interval=4, wait_screen_change=0, wait_still_screen=0, timeout=30, similarity_level=47)
[2024-05-28T08:14:36.541964Z] [debug] [pid:2759] tests/installation/bootloader_start.pm:84 called bootloader::run -> tests/installation/bootloader.pm:56 called bootloader_setup::specific_bootmenu_params -> lib/bootloader_setup.pm:913 called bootloader_setup::type_boot_parameters -> lib/bootloader_setup.pm:1592 called testapi::type_string
[2024-05-28T08:14:36.542257Z] [debug] [pid:2759] <<< testapi::type_string(string="  ifcfg=*=dhcp SetHostname=0 autoyast=http://10.0.2.2:20303/BNGyhHHiGaVcXGrV/files/autoyast_opensuse/autoyast_multi_btrfs.xml kernel.softlockup_panic=1  ", max_interval=4, wait_screen_change=0, wait_still_screen=0, timeout=30, similarity_level=47)
[2024-05-28T08:16:03.361386Z] [debug] [pid:2759] tests/installation/bootloader_start.pm:84 called bootloader::run -> tests/installation/bootloader.pm:68 called testapi::send_key
[2024-05-28T08:16:03.361518Z] [debug] [pid:2759] <<< testapi::send_key(key="ret", wait_screen_change=0)
[2024-05-28T08:16:03.629352Z] [debug] [pid:2759] tests/installation/bootloader_start.pm:84 called bootloader::run -> tests/installation/bootloader.pm:71 called bootloader_setup::parse_bootparams_in_serial -> lib/bootloader_setup.pm:1507 called testapi::wait_serial
[2024-05-28T08:16:03.629570Z] [debug] [pid:2759] <<< testapi::wait_serial(no_regex=0, quiet=undef, regexp=qr/command line:.*\[/msi, buffer_size=undef, timeout=90, record_output=undef, expect_not_found=0)
[32m[2024-05-28T08:16:05.682261Z] [debug] [pid:2759] >>> testapi::wait_serial: (?^msi:command line:.*\[): ok[0m
[2024-05-28T08:16:05.682451Z] [debug] [pid:2759] tests/installation/bootloader_start.pm:84 called bootloader::run -> tests/installation/bootloader.pm:71 called bootloader_setup::compare_bootparams -> lib/bootloader_setup.pm:1530 called testapi::record_info
[2024-05-28T08:16:05.682605Z] [debug] [pid:2759] <<< testapi::record_info(title="params ok", output="Bootloader parameters are typed correctly.\nVerified parameters:\nY2DEBUG=1\nvga=791\nvideo=1024x768\nplymouth.ignore-serial-consoles\nconsole=ttyS0\nconsole=tty\nlinuxrc.log=/dev/ttyS0\nlinuxrc.core=/dev/ttyS0\nlinuxrc.debug=4,trace\nreboot_timeout=0\nifcfg=*=dhcp\nSetHostname=0\nautoyast=http://10.0.2.2:20303/BNGyhHHiGaVcXGrV/files/autoyast_opensuse/autoyast_multi_btrfs.xml\nkernel.softlockup_panic=1", result="ok")
[1;34m[2024-05-28T08:16:05.686405Z] [debug] [pid:2759] ||| finished bootloader_start installation (runtime: 193 s)[0m
[1;34m[2024-05-28T08:16:05.687444Z] [debug] [pid:2759] ||| starting installation tests/autoyast/installation.pm[0m
[2024-05-28T08:16:05.701070Z] [debug] [pid:2759] tests/autoyast/installation.pm:109 called autoyast::test_ayp_url -> lib/autoyast.pm:800 called testapi::record_info
[2024-05-28T08:16:05.701202Z] [debug] [pid:2759] <<< testapi::record_info(title="ayp url ok", output="Autoyast profile url http://localhost:20303/BNGyhHHiGaVcXGrV/files/autoyast_opensuse/autoyast_multi_btrfs.xml is reachable from the worker", result="ok")
[2024-05-28T08:16:05.701551Z] [debug] [pid:2759] tests/autoyast/installation.pm:169 called testapi::check_screen
[2024-05-28T08:16:05.701668Z] [debug] [pid:2759] <<< testapi::check_screen(mustmatch=[
    "bios-boot",
    "nonexisting-package",
    "reboot-after-installation",
    "linuxrc-install-fail",
    "scc-invalid-url",
    "warning-pop-up",
    "autoyast-boot",
    "package-notification",
    "nvidia-validation-failed",
    "import-untrusted-gpg-key",
    "autoyast-error",
    "manual-intervention",
    "opensuse-welcome"
  ], timeout=50)
[31m[2024-05-28T08:16:09.181795Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 3.48 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:16:09.181891Z] [debug] [pid:3081] no match: 49.9s, best candidate: consoletest_finish-gnome-20191211 (0.22)[0m
[37m[2024-05-28T08:16:09.182287Z] [debug] [pid:3081] pointer type 1 0 1024 768 -257[0m
[31m[2024-05-28T08:16:10.986920Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.80 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:16:10.987017Z] [debug] [pid:3081] no match: 46.5s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T08:16:12.795230Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.81 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:16:12.795332Z] [debug] [pid:3081] no match: 44.7s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T08:16:14.756779Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.96 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:16:14.756865Z] [debug] [pid:3081] no match: 42.9s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T08:16:20.236464Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 5.48 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:16:20.236555Z] [debug] [pid:3081] no match: 40.9s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[37m[2024-05-28T08:16:20.239029Z] [debug] [pid:3081] no change: 35.4s[0m
[31m[2024-05-28T08:16:25.436177Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 5.20 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:16:25.436271Z] [debug] [pid:3081] no match: 35.4s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T08:16:31.037383Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 5.59 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:16:31.037477Z] [debug] [pid:3081] no match: 30.2s, best candidate: consoletest_finish-gnome-20150915 (0.05)[0m
[31m[2024-05-28T08:16:33.026208Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.98 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:16:33.026295Z] [debug] [pid:3081] no match: 24.6s, best candidate: consoletest_finish-gnome-20150915 (0.05)[0m
[31m[2024-05-28T08:16:35.052807Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 2.02 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:16:35.052891Z] [debug] [pid:3081] no match: 22.6s, best candidate: consoletest_finish-gnome-20150915 (0.05)[0m
[31m[2024-05-28T08:16:40.597586Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 5.54 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:16:40.597680Z] [debug] [pid:3081] no match: 20.6s, best candidate: consoletest_finish-gnome-20150915 (0.05)[0m
[31m[2024-05-28T08:16:46.054957Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 5.45 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:16:46.055047Z] [debug] [pid:3081] no match: 15.1s, best candidate: consoletest_finish-gnome-20150915 (0.05)[0m
[31m[2024-05-28T08:16:48.083002Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 2.02 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:16:48.083093Z] [debug] [pid:3081] no match: 9.6s, best candidate: consoletest_finish-gnome-20150915 (0.05)[0m
[31m[2024-05-28T08:16:50.124390Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 2.04 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:16:50.124482Z] [debug] [pid:3081] no match: 7.6s, best candidate: consoletest_finish-gnome-20150915 (0.05)[0m
[31m[2024-05-28T08:16:55.759589Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 5.63 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:16:55.759674Z] [debug] [pid:3081] no match: 5.5s, best candidate: consoletest_finish-gnome-20150915 (0.05)[0m
[31m[2024-05-28T08:17:01.235587Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 5.47 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:17:01.235679Z] [debug] [pid:3081] no match: -0.1s, best candidate: consoletest_finish-gnome-20191211 (0.19)[0m
[32m[2024-05-28T08:17:01.428188Z] [debug] [pid:2759] >>> testapi::_check_backend_response: match=autoyast-boot,autoyast-error,bios-boot,import-untrusted-gpg-key,linuxrc-install-fail,manual-intervention,nonexisting-package,nvidia-validation-failed,opensuse-welcome,package-notification,reboot-after-installation,scc-invalid-url,warning-pop-up timed out after 50 (check_screen)[0m
[2024-05-28T08:17:01.445639Z] [debug] [pid:2759] tests/autoyast/installation.pm:179 called installation::verify_timeout_and_check_screen -> tests/autoyast/installation.pm:103 called testapi::check_screen
[2024-05-28T08:17:01.445785Z] [debug] [pid:2759] <<< testapi::check_screen(mustmatch=[
    "bios-boot",
    "nonexisting-package",
    "reboot-after-installation",
    "linuxrc-install-fail",
    "scc-invalid-url",
    "warning-pop-up",
    "autoyast-boot",
    "package-notification",
    "nvidia-validation-failed",
    "import-untrusted-gpg-key",
    "autoyast-error",
    "manual-intervention",
    "opensuse-welcome"
  ], timeout=50)
[31m[2024-05-28T08:17:04.405692Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 2.96 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:17:04.405795Z] [debug] [pid:3081] no match: 49.9s, best candidate: consoletest_finish-gnome-20191211 (0.22)[0m
[31m[2024-05-28T08:17:06.213143Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.80 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:17:06.213228Z] [debug] [pid:3081] no match: 47.0s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T08:17:11.416545Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 5.20 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:17:11.416639Z] [debug] [pid:3081] no match: 45.2s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T08:17:16.728627Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 5.31 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:17:16.728720Z] [debug] [pid:3081] no match: 40.0s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T08:17:18.511827Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.78 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:17:18.511914Z] [debug] [pid:3081] no match: 34.7s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T08:17:20.296215Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.78 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:17:20.296303Z] [debug] [pid:3081] no match: 32.9s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[37m[2024-05-28T08:17:20.298706Z] [debug] [pid:3081] no change: 31.1s[0m
[31m[2024-05-28T08:17:22.085468Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.79 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:17:22.085563Z] [debug] [pid:3081] no match: 31.1s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[37m[2024-05-28T08:17:22.088026Z] [debug] [pid:3081] no change: 29.3s[0m
[31m[2024-05-28T08:17:23.870617Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.78 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:17:23.870704Z] [debug] [pid:3081] no match: 29.3s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T08:17:25.656439Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.78 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:17:25.656538Z] [debug] [pid:3081] no match: 27.5s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T08:17:30.864035Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 5.20 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:17:30.864138Z] [debug] [pid:3081] no match: 25.7s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T08:17:36.025953Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 5.16 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:17:36.026042Z] [debug] [pid:3081] no match: 20.5s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T08:17:41.241886Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 5.21 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:17:41.241986Z] [debug] [pid:3081] no match: 15.4s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T08:17:46.466503Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 5.22 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:17:46.466604Z] [debug] [pid:3081] no match: 10.1s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T08:17:48.290946Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.82 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:17:48.291044Z] [debug] [pid:3081] no match: 4.9s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T08:17:50.089709Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.79 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:17:50.089806Z] [debug] [pid:3081] no match: 3.1s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T08:17:51.900892Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.81 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:17:51.900976Z] [debug] [pid:3081] no match: 1.3s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T08:17:57.135335Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 5.23 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:17:57.135426Z] [debug] [pid:3081] no match: -0.5s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[32m[2024-05-28T08:17:57.296528Z] [debug] [pid:2759] >>> testapi::_check_backend_response: match=autoyast-boot,autoyast-error,bios-boot,import-untrusted-gpg-key,linuxrc-install-fail,manual-intervention,nonexisting-package,nvidia-validation-failed,opensuse-welcome,package-notification,reboot-after-installation,scc-invalid-url,warning-pop-up timed out after 50 (check_screen)[0m
[2024-05-28T08:17:57.312244Z] [debug] [pid:2759] tests/autoyast/installation.pm:179 called installation::verify_timeout_and_check_screen -> tests/autoyast/installation.pm:103 called testapi::check_screen
[2024-05-28T08:17:57.312394Z] [debug] [pid:2759] <<< testapi::check_screen(mustmatch=[
    "bios-boot",
    "nonexisting-package",
    "reboot-after-installation",
    "linuxrc-install-fail",
    "scc-invalid-url",
    "warning-pop-up",
    "autoyast-boot",
    "package-notification",
    "nvidia-validation-failed",
    "import-untrusted-gpg-key",
    "autoyast-error",
    "manual-intervention",
    "opensuse-welcome"
  ], timeout=50)
[31m[2024-05-28T08:18:00.021061Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 2.71 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:18:00.021151Z] [debug] [pid:3081] no match: 49.9s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T08:18:01.799782Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.78 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:18:01.799877Z] [debug] [pid:3081] no match: 47.2s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T08:18:07.097106Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 5.29 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:18:07.097205Z] [debug] [pid:3081] no match: 45.5s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T08:18:12.297237Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 5.20 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:18:12.297336Z] [debug] [pid:3081] no match: 40.2s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T08:18:17.525945Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 5.22 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:18:17.526045Z] [debug] [pid:3081] no match: 35.0s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T08:18:19.310595Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.78 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:18:19.310699Z] [debug] [pid:3081] no match: 29.7s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T08:18:21.132061Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.82 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:18:21.132163Z] [debug] [pid:3081] no match: 27.9s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T08:18:22.964344Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.83 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:18:22.964444Z] [debug] [pid:3081] no match: 26.1s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T08:18:24.748259Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.78 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:18:24.748352Z] [debug] [pid:3081] no match: 24.3s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T08:18:26.525690Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.77 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:18:26.525791Z] [debug] [pid:3081] no match: 22.5s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T08:18:31.684373Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 5.15 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:18:31.684471Z] [debug] [pid:3081] no match: 20.7s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T08:18:36.888932Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 5.20 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:18:36.889038Z] [debug] [pid:3081] no match: 15.6s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T08:18:42.090344Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 5.19 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:18:42.090443Z] [debug] [pid:3081] no match: 10.4s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T08:18:47.304099Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 5.21 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:18:47.304195Z] [debug] [pid:3081] no match: 5.2s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T08:18:52.536974Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 5.23 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:18:52.537075Z] [debug] [pid:3081] no match: -0.0s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T08:18:57.909783Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 5.37 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:18:57.909883Z] [debug] [pid:3081] no match: -5.3s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[32m[2024-05-28T08:18:58.019045Z] [debug] [pid:2759] >>> testapi::_check_backend_response: match=autoyast-boot,autoyast-error,bios-boot,import-untrusted-gpg-key,linuxrc-install-fail,manual-intervention,nonexisting-package,nvidia-validation-failed,opensuse-welcome,package-notification,reboot-after-installation,scc-invalid-url,warning-pop-up timed out after 50 (check_screen)[0m
[2024-05-28T08:18:58.038319Z] [debug] [pid:2759] tests/autoyast/installation.pm:179 called installation::verify_timeout_and_check_screen -> tests/autoyast/installation.pm:103 called testapi::check_screen
[2024-05-28T08:18:58.038509Z] [debug] [pid:2759] <<< testapi::check_screen(mustmatch=[
    "bios-boot",
    "nonexisting-package",
    "reboot-after-installation",
    "linuxrc-install-fail",
    "scc-invalid-url",
    "warning-pop-up",
    "autoyast-boot",
    "package-notification",
    "nvidia-validation-failed",
    "import-untrusted-gpg-key",
    "autoyast-error",
    "manual-intervention",
    "opensuse-welcome"
  ], timeout=50)
[31m[2024-05-28T08:19:00.711370Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 2.67 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:19:00.711453Z] [debug] [pid:3081] no match: 49.9s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T08:19:02.539546Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.82 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:19:02.539641Z] [debug] [pid:3081] no match: 47.3s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T08:19:07.939888Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 5.40 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:19:07.939980Z] [debug] [pid:3081] no match: 45.4s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T08:19:13.273595Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 5.33 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:19:13.273682Z] [debug] [pid:3081] no match: 40.0s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T08:19:15.082715Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.80 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:19:15.082814Z] [debug] [pid:3081] no match: 34.7s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T08:19:16.871118Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.78 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:19:16.871202Z] [debug] [pid:3081] no match: 32.9s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T08:19:18.674696Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.80 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:19:18.674780Z] [debug] [pid:3081] no match: 31.1s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T08:19:20.470462Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.79 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:19:20.470545Z] [debug] [pid:3081] no match: 29.3s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T08:19:22.291196Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.82 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:19:22.291287Z] [debug] [pid:3081] no match: 27.5s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T08:19:27.587866Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 5.29 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:19:27.587978Z] [debug] [pid:3081] no match: 25.7s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T08:19:32.870671Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 5.28 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:19:32.870762Z] [debug] [pid:3081] no match: 20.4s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T08:19:38.188360Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 5.31 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:19:38.188459Z] [debug] [pid:3081] no match: 15.1s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T08:19:39.997504Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.80 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:19:39.997597Z] [debug] [pid:3081] no match: 9.8s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[37m[2024-05-28T08:19:40.002118Z] [debug] [pid:3081] no change: 8.0s[0m
[31m[2024-05-28T08:19:41.801376Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.80 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:19:41.801475Z] [debug] [pid:3081] no match: 8.0s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T08:19:43.667557Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.86 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:19:43.667646Z] [debug] [pid:3081] no match: 6.2s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T08:19:45.478598Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.81 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:19:45.478689Z] [debug] [pid:3081] no match: 4.3s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[37m[2024-05-28T08:19:45.481090Z] [debug] [pid:3081] no change: 2.5s[0m
[31m[2024-05-28T08:19:47.271795Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.79 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:19:47.271884Z] [debug] [pid:3081] no match: 2.5s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T08:19:52.604896Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 5.33 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:19:52.604997Z] [debug] [pid:3081] no match: 0.7s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T08:19:58.058531Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 5.45 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:19:58.058630Z] [debug] [pid:3081] no match: -4.6s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[32m[2024-05-28T08:19:58.160080Z] [debug] [pid:2759] >>> testapi::_check_backend_response: match=autoyast-boot,autoyast-error,bios-boot,import-untrusted-gpg-key,linuxrc-install-fail,manual-intervention,nonexisting-package,nvidia-validation-failed,opensuse-welcome,package-notification,reboot-after-installation,scc-invalid-url,warning-pop-up timed out after 50 (check_screen)[0m
[2024-05-28T08:19:58.174243Z] [debug] [pid:2759] tests/autoyast/installation.pm:179 called installation::verify_timeout_and_check_screen -> tests/autoyast/installation.pm:103 called testapi::check_screen
[2024-05-28T08:19:58.174411Z] [debug] [pid:2759] <<< testapi::check_screen(mustmatch=[
    "bios-boot",
    "nonexisting-package",
    "reboot-after-installation",
    "linuxrc-install-fail",
    "scc-invalid-url",
    "warning-pop-up",
    "autoyast-boot",
    "package-notification",
    "nvidia-validation-failed",
    "import-untrusted-gpg-key",
    "autoyast-error",
    "manual-intervention",
    "opensuse-welcome"
  ], timeout=50)
[31m[2024-05-28T08:20:00.865654Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 2.69 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:20:00.865741Z] [debug] [pid:3081] no match: 49.9s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T08:20:02.689612Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.82 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:20:02.689711Z] [debug] [pid:3081] no match: 47.3s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T08:20:08.072979Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 5.38 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:20:08.073077Z] [debug] [pid:3081] no match: 45.4s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T08:20:13.622861Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 5.55 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:20:13.622956Z] [debug] [pid:3081] no match: 40.0s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T08:20:15.493541Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.86 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:20:15.493632Z] [debug] [pid:3081] no match: 34.5s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T08:20:17.327073Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.83 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:20:17.327165Z] [debug] [pid:3081] no match: 32.6s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T08:20:22.757550Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 5.43 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:20:22.757647Z] [debug] [pid:3081] no match: 30.8s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T08:20:28.003309Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 5.24 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:20:28.003410Z] [debug] [pid:3081] no match: 25.4s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T08:20:33.202299Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 5.19 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:20:33.202397Z] [debug] [pid:3081] no match: 20.1s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T08:20:35.016395Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.81 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:20:35.016490Z] [debug] [pid:3081] no match: 14.9s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T08:20:36.825954Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.80 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:20:36.826057Z] [debug] [pid:3081] no match: 13.1s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T08:20:38.617789Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.79 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:20:38.617897Z] [debug] [pid:3081] no match: 11.3s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T08:20:40.413273Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.79 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:20:40.413371Z] [debug] [pid:3081] no match: 9.5s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[37m[2024-05-28T08:20:40.416381Z] [debug] [pid:3081] no change: 7.7s[0m
[31m[2024-05-28T08:20:42.191254Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.77 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:20:42.191347Z] [debug] [pid:3081] no match: 7.7s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T08:20:47.419692Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 5.23 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:20:47.419780Z] [debug] [pid:3081] no match: 5.9s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T08:20:52.638148Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 5.21 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:20:52.638235Z] [debug] [pid:3081] no match: 0.7s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T08:20:57.847423Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 5.20 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:20:57.847511Z] [debug] [pid:3081] no match: -4.5s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[32m[2024-05-28T08:20:57.952191Z] [debug] [pid:2759] >>> testapi::_check_backend_response: match=autoyast-boot,autoyast-error,bios-boot,import-untrusted-gpg-key,linuxrc-install-fail,manual-intervention,nonexisting-package,nvidia-validation-failed,opensuse-welcome,package-notification,reboot-after-installation,scc-invalid-url,warning-pop-up timed out after 50 (check_screen)[0m
[2024-05-28T08:20:57.966925Z] [debug] [pid:2759] tests/autoyast/installation.pm:179 called installation::verify_timeout_and_check_screen -> tests/autoyast/installation.pm:103 called testapi::check_screen
[2024-05-28T08:20:57.967110Z] [debug] [pid:2759] <<< testapi::check_screen(mustmatch=[
    "bios-boot",
    "nonexisting-package",
    "reboot-after-installation",
    "linuxrc-install-fail",
    "scc-invalid-url",
    "warning-pop-up",
    "autoyast-boot",
    "package-notification",
    "nvidia-validation-failed",
    "import-untrusted-gpg-key",
    "autoyast-error",
    "manual-intervention",
    "opensuse-welcome"
  ], timeout=50)
[31m[2024-05-28T08:21:00.676347Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 2.71 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:21:00.676429Z] [debug] [pid:3081] no match: 49.9s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T08:21:02.466460Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.79 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:21:02.466550Z] [debug] [pid:3081] no match: 47.2s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T08:21:07.853437Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 5.38 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:21:07.853531Z] [debug] [pid:3081] no match: 45.4s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T08:21:13.171559Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 5.31 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:21:13.171666Z] [debug] [pid:3081] no match: 40.1s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T08:21:14.989299Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.81 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:21:14.989397Z] [debug] [pid:3081] no match: 34.7s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T08:21:16.782132Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.79 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:21:16.782227Z] [debug] [pid:3081] no match: 32.9s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[37m[2024-05-28T08:21:16.784837Z] [debug] [pid:3081] no change: 31.1s[0m
[31m[2024-05-28T08:21:18.585745Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.80 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:21:18.585831Z] [debug] [pid:3081] no match: 31.1s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T08:21:20.377156Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.79 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:21:20.377256Z] [debug] [pid:3081] no match: 29.3s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[37m[2024-05-28T08:21:20.379752Z] [debug] [pid:3081] no change: 27.5s[0m
[31m[2024-05-28T08:21:22.169848Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.79 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:21:22.169940Z] [debug] [pid:3081] no match: 27.5s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T08:21:27.358494Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 5.19 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:21:27.358579Z] [debug] [pid:3081] no match: 25.7s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T08:21:32.515797Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 5.15 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:21:32.515882Z] [debug] [pid:3081] no match: 20.6s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T08:21:37.734265Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 5.21 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:21:37.734356Z] [debug] [pid:3081] no match: 15.4s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T08:21:42.896506Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 5.16 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:21:42.896592Z] [debug] [pid:3081] no match: 10.2s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T08:21:48.105976Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 5.20 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:21:48.106074Z] [debug] [pid:3081] no match: 5.0s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T08:21:53.321109Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 5.21 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:21:53.321199Z] [debug] [pid:3081] no match: -0.2s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[32m[2024-05-28T08:21:53.430234Z] [debug] [pid:2759] >>> testapi::_check_backend_response: match=autoyast-boot,autoyast-error,bios-boot,import-untrusted-gpg-key,linuxrc-install-fail,manual-intervention,nonexisting-package,nvidia-validation-failed,opensuse-welcome,package-notification,reboot-after-installation,scc-invalid-url,warning-pop-up timed out after 50 (check_screen)[0m
[2024-05-28T08:21:53.450068Z] [debug] [pid:2759] tests/autoyast/installation.pm:179 called installation::verify_timeout_and_check_screen -> tests/autoyast/installation.pm:103 called testapi::check_screen
[2024-05-28T08:21:53.450318Z] [debug] [pid:2759] <<< testapi::check_screen(mustmatch=[
    "bios-boot",
    "nonexisting-package",
    "reboot-after-installation",
    "linuxrc-install-fail",
    "scc-invalid-url",
    "warning-pop-up",
    "autoyast-boot",
    "package-notification",
    "nvidia-validation-failed",
    "import-untrusted-gpg-key",
    "autoyast-error",
    "manual-intervention",
    "opensuse-welcome"
  ], timeout=50)
[31m[2024-05-28T08:21:56.273913Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 2.82 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:21:56.274001Z] [debug] [pid:3081] no match: 49.9s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T08:21:58.081552Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.80 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:21:58.081645Z] [debug] [pid:3081] no match: 47.1s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T08:22:03.468337Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 5.38 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:22:03.468422Z] [debug] [pid:3081] no match: 45.3s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T08:22:05.302147Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.83 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:22:05.302237Z] [debug] [pid:3081] no match: 39.9s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T08:22:07.155001Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.85 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:22:07.155081Z] [debug] [pid:3081] no match: 38.1s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[37m[2024-05-28T08:22:07.157721Z] [debug] [pid:3081] no change: 36.2s[0m
[31m[2024-05-28T08:22:08.983275Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.83 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:22:08.983365Z] [debug] [pid:3081] no match: 36.2s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T08:22:10.803741Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.82 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:22:10.803825Z] [debug] [pid:3081] no match: 34.4s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[37m[2024-05-28T08:22:10.806222Z] [debug] [pid:3081] no change: 32.6s[0m
[31m[2024-05-28T08:22:12.637314Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.83 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:22:12.637398Z] [debug] [pid:3081] no match: 32.6s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T08:22:17.930468Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 5.29 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:22:17.930556Z] [debug] [pid:3081] no match: 30.8s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[37m[2024-05-28T08:22:17.934142Z] [debug] [pid:3081] no change: 25.5s[0m
[31m[2024-05-28T08:22:23.233014Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 5.30 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:22:23.233102Z] [debug] [pid:3081] no match: 25.5s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T08:22:28.496308Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 5.26 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:22:28.496414Z] [debug] [pid:3081] no match: 20.2s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[37m[2024-05-28T08:22:28.502210Z] [debug] [pid:3081] no change: 14.9s[0m
[31m[2024-05-28T08:22:30.313752Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.81 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:22:30.313842Z] [debug] [pid:3081] no match: 14.9s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[37m[2024-05-28T08:22:30.318521Z] [debug] [pid:3081] no change: 13.1s[0m
[31m[2024-05-28T08:22:32.132541Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.81 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:22:32.132631Z] [debug] [pid:3081] no match: 13.1s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[37m[2024-05-28T08:22:32.135241Z] [debug] [pid:3081] no change: 11.3s[0m
[31m[2024-05-28T08:22:34.005108Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.87 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:22:34.005194Z] [debug] [pid:3081] no match: 11.3s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T08:22:35.805387Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.80 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:22:35.805472Z] [debug] [pid:3081] no match: 9.4s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[37m[2024-05-28T08:22:35.807959Z] [debug] [pid:3081] no change: 7.6s[0m
[31m[2024-05-28T08:22:37.607001Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.80 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:22:37.607094Z] [debug] [pid:3081] no match: 7.6s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T08:22:43.027951Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 5.42 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:22:43.028050Z] [debug] [pid:3081] no match: 5.8s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T08:22:48.373083Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 5.34 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:22:48.373171Z] [debug] [pid:3081] no match: 0.4s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T08:22:53.704530Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 5.32 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:22:53.704616Z] [debug] [pid:3081] no match: -5.0s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[32m[2024-05-28T08:22:53.816426Z] [debug] [pid:2759] >>> testapi::_check_backend_response: match=autoyast-boot,autoyast-error,bios-boot,import-untrusted-gpg-key,linuxrc-install-fail,manual-intervention,nonexisting-package,nvidia-validation-failed,opensuse-welcome,package-notification,reboot-after-installation,scc-invalid-url,warning-pop-up timed out after 50 (check_screen)[0m
[2024-05-28T08:22:53.831913Z] [debug] [pid:2759] tests/autoyast/installation.pm:179 called installation::verify_timeout_and_check_screen -> tests/autoyast/installation.pm:103 called testapi::check_screen
[2024-05-28T08:22:53.832125Z] [debug] [pid:2759] <<< testapi::check_screen(mustmatch=[
    "bios-boot",
    "nonexisting-package",
    "reboot-after-installation",
    "linuxrc-install-fail",
    "scc-invalid-url",
    "warning-pop-up",
    "autoyast-boot",
    "package-notification",
    "nvidia-validation-failed",
    "import-untrusted-gpg-key",
    "autoyast-error",
    "manual-intervention",
    "opensuse-welcome"
  ], timeout=50)
[31m[2024-05-28T08:22:56.538953Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 2.70 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:22:56.539036Z] [debug] [pid:3081] no match: 49.9s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T08:22:58.340113Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.80 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:22:58.340215Z] [debug] [pid:3081] no match: 47.2s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T08:23:03.677789Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 5.33 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:23:03.677895Z] [debug] [pid:3081] no match: 45.4s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T08:23:09.056286Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 5.37 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:23:09.056375Z] [debug] [pid:3081] no match: 40.1s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T08:23:10.850392Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.79 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:23:10.850474Z] [debug] [pid:3081] no match: 34.7s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T08:23:12.646664Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.79 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:23:12.646757Z] [debug] [pid:3081] no match: 32.9s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[37m[2024-05-28T08:23:12.649702Z] [debug] [pid:3081] no change: 31.1s[0m
[31m[2024-05-28T08:23:14.445290Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.80 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:23:14.445386Z] [debug] [pid:3081] no match: 31.1s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T08:23:16.237589Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.79 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:23:16.237693Z] [debug] [pid:3081] no match: 29.3s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T08:23:18.048650Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.81 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:23:18.048743Z] [debug] [pid:3081] no match: 27.5s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T08:23:23.274559Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 5.22 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:23:23.274645Z] [debug] [pid:3081] no match: 25.7s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T08:23:28.535863Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 5.26 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:23:28.535949Z] [debug] [pid:3081] no match: 20.5s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T08:23:33.846747Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 5.30 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:23:33.846842Z] [debug] [pid:3081] no match: 15.2s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T08:23:35.642091Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.79 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:23:35.642175Z] [debug] [pid:3081] no match: 9.9s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T08:23:37.435533Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.79 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:23:37.435625Z] [debug] [pid:3081] no match: 8.1s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T08:23:39.307961Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.87 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:23:39.308062Z] [debug] [pid:3081] no match: 6.3s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T08:23:41.138619Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.83 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:23:41.138708Z] [debug] [pid:3081] no match: 4.5s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T08:23:42.937998Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.80 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:23:42.938080Z] [debug] [pid:3081] no match: 2.6s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T08:23:48.129914Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 5.19 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:23:48.130023Z] [debug] [pid:3081] no match: 0.8s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T08:23:53.326751Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 5.19 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:23:53.326840Z] [debug] [pid:3081] no match: -4.4s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[32m[2024-05-28T08:23:53.423081Z] [debug] [pid:2759] >>> testapi::_check_backend_response: match=autoyast-boot,autoyast-error,bios-boot,import-untrusted-gpg-key,linuxrc-install-fail,manual-intervention,nonexisting-package,nvidia-validation-failed,opensuse-welcome,package-notification,reboot-after-installation,scc-invalid-url,warning-pop-up timed out after 50 (check_screen)[0m
[2024-05-28T08:23:53.437854Z] [debug] [pid:2759] tests/autoyast/installation.pm:179 called installation::verify_timeout_and_check_screen -> tests/autoyast/installation.pm:103 called testapi::check_screen
[2024-05-28T08:23:53.438046Z] [debug] [pid:2759] <<< testapi::check_screen(mustmatch=[
    "bios-boot",
    "nonexisting-package",
    "reboot-after-installation",
    "linuxrc-install-fail",
    "scc-invalid-url",
    "warning-pop-up",
    "autoyast-boot",
    "package-notification",
    "nvidia-validation-failed",
    "import-untrusted-gpg-key",
    "autoyast-error",
    "manual-intervention",
    "opensuse-welcome"
  ], timeout=50)
[31m[2024-05-28T08:23:56.123803Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 2.68 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:23:56.123907Z] [debug] [pid:3081] no match: 49.9s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T08:23:57.942260Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.81 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:23:57.942349Z] [debug] [pid:3081] no match: 47.3s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T08:24:03.234928Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 5.29 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:24:03.235022Z] [debug] [pid:3081] no match: 45.4s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T08:24:08.583729Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 5.34 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:24:08.583824Z] [debug] [pid:3081] no match: 40.2s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T08:24:10.428258Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.84 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:24:10.428347Z] [debug] [pid:3081] no match: 34.8s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T08:24:12.261390Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.83 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:24:12.261481Z] [debug] [pid:3081] no match: 33.0s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T08:24:14.134515Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.87 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:24:14.134601Z] [debug] [pid:3081] no match: 31.1s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T08:24:16.065528Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.93 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:24:16.065624Z] [debug] [pid:3081] no match: 29.3s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[37m[2024-05-28T08:24:16.068125Z] [debug] [pid:3081] no change: 27.3s[0m
[31m[2024-05-28T08:24:17.868444Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.80 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:24:17.868541Z] [debug] [pid:3081] no match: 27.3s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T08:24:23.130758Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 5.26 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:24:23.130844Z] [debug] [pid:3081] no match: 25.5s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[37m[2024-05-28T08:24:23.134474Z] [debug] [pid:3081] no change: 20.3s[0m
[31m[2024-05-28T08:24:28.358183Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 5.22 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:24:28.358270Z] [debug] [pid:3081] no match: 20.3s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T08:24:33.574801Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 5.21 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:24:33.574886Z] [debug] [pid:3081] no match: 15.0s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T08:24:35.366917Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.79 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:24:35.367015Z] [debug] [pid:3081] no match: 9.8s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T08:24:37.198601Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.83 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:24:37.198697Z] [debug] [pid:3081] no match: 8.0s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T08:24:38.993484Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.79 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:24:38.993575Z] [debug] [pid:3081] no match: 6.2s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[37m[2024-05-28T08:24:38.996129Z] [debug] [pid:3081] no change: 4.4s[0m
[31m[2024-05-28T08:24:40.770890Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.77 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:24:40.770990Z] [debug] [pid:3081] no match: 4.4s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T08:24:42.571554Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.80 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:24:42.571650Z] [debug] [pid:3081] no match: 2.6s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T08:24:47.775982Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 5.20 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:24:47.776094Z] [debug] [pid:3081] no match: 0.8s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T08:24:52.966004Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 5.19 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:24:52.966093Z] [debug] [pid:3081] no match: -4.4s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[32m[2024-05-28T08:24:53.062276Z] [debug] [pid:2759] >>> testapi::_check_backend_response: match=autoyast-boot,autoyast-error,bios-boot,import-untrusted-gpg-key,linuxrc-install-fail,manual-intervention,nonexisting-package,nvidia-validation-failed,opensuse-welcome,package-notification,reboot-after-installation,scc-invalid-url,warning-pop-up timed out after 50 (check_screen)[0m
[2024-05-28T08:24:53.078029Z] [debug] [pid:2759] tests/autoyast/installation.pm:179 called installation::verify_timeout_and_check_screen -> tests/autoyast/installation.pm:103 called testapi::check_screen
[2024-05-28T08:24:53.078217Z] [debug] [pid:2759] <<< testapi::check_screen(mustmatch=[
    "bios-boot",
    "nonexisting-package",
    "reboot-after-installation",
    "linuxrc-install-fail",
    "scc-invalid-url",
    "warning-pop-up",
    "autoyast-boot",
    "package-notification",
    "nvidia-validation-failed",
    "import-untrusted-gpg-key",
    "autoyast-error",
    "manual-intervention",
    "opensuse-welcome"
  ], timeout=50)
[31m[2024-05-28T08:24:55.786483Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 2.70 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:24:55.786581Z] [debug] [pid:3081] no match: 49.9s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T08:24:57.630626Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.84 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:24:57.630725Z] [debug] [pid:3081] no match: 47.2s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T08:25:02.990255Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 5.36 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:25:02.990348Z] [debug] [pid:3081] no match: 45.4s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T08:25:08.430089Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 5.44 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:25:08.430174Z] [debug] [pid:3081] no match: 40.0s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T08:25:10.270439Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.83 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:25:10.270528Z] [debug] [pid:3081] no match: 34.6s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T08:25:12.062002Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.79 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:25:12.062099Z] [debug] [pid:3081] no match: 32.8s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[37m[2024-05-28T08:25:12.064439Z] [debug] [pid:3081] no change: 31.0s[0m
[31m[2024-05-28T08:25:13.888047Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.82 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:25:13.888143Z] [debug] [pid:3081] no match: 31.0s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T08:25:15.704961Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.81 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:25:15.705048Z] [debug] [pid:3081] no match: 29.1s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T08:25:17.505069Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.80 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:25:17.505165Z] [debug] [pid:3081] no match: 27.3s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T08:25:22.836047Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 5.33 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:25:22.836142Z] [debug] [pid:3081] no match: 25.5s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T08:25:28.139494Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 5.30 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:25:28.139579Z] [debug] [pid:3081] no match: 20.2s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T08:25:29.968628Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.82 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:25:29.968713Z] [debug] [pid:3081] no match: 14.9s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T08:25:31.788492Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.81 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:25:31.788581Z] [debug] [pid:3081] no match: 13.1s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T08:25:33.594902Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.80 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:25:33.594991Z] [debug] [pid:3081] no match: 11.2s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T08:25:35.403990Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.81 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:25:35.404084Z] [debug] [pid:3081] no match: 9.4s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T08:25:37.214947Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.81 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:25:37.215028Z] [debug] [pid:3081] no match: 7.6s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T08:25:42.474887Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 5.26 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:25:42.474991Z] [debug] [pid:3081] no match: 5.8s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T08:25:47.681010Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 5.20 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:25:47.681091Z] [debug] [pid:3081] no match: 0.5s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T08:25:52.900441Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 5.21 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:25:52.900540Z] [debug] [pid:3081] no match: -4.7s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[32m[2024-05-28T08:25:52.994951Z] [debug] [pid:2759] >>> testapi::_check_backend_response: match=autoyast-boot,autoyast-error,bios-boot,import-untrusted-gpg-key,linuxrc-install-fail,manual-intervention,nonexisting-package,nvidia-validation-failed,opensuse-welcome,package-notification,reboot-after-installation,scc-invalid-url,warning-pop-up timed out after 50 (check_screen)[0m
[2024-05-28T08:25:53.009835Z] [debug] [pid:2759] tests/autoyast/installation.pm:179 called installation::verify_timeout_and_check_screen -> tests/autoyast/installation.pm:103 called testapi::check_screen
[2024-05-28T08:25:53.010010Z] [debug] [pid:2759] <<< testapi::check_screen(mustmatch=[
    "bios-boot",
    "nonexisting-package",
    "reboot-after-installation",
    "linuxrc-install-fail",
    "scc-invalid-url",
    "warning-pop-up",
    "autoyast-boot",
    "package-notification",
    "nvidia-validation-failed",
    "import-untrusted-gpg-key",
    "autoyast-error",
    "manual-intervention",
    "opensuse-welcome"
  ], timeout=50)
[31m[2024-05-28T08:25:55.758225Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 2.75 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:25:55.758322Z] [debug] [pid:3081] no match: 49.9s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T08:25:57.552240Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.79 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:25:57.552334Z] [debug] [pid:3081] no match: 47.2s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T08:26:02.950655Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 5.39 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:26:02.950751Z] [debug] [pid:3081] no match: 45.4s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T08:26:08.315403Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 5.36 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:26:08.315501Z] [debug] [pid:3081] no match: 40.0s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T08:26:10.132176Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.81 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:26:10.132275Z] [debug] [pid:3081] no match: 34.6s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T08:26:11.965033Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.83 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:26:11.965133Z] [debug] [pid:3081] no match: 32.8s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[37m[2024-05-28T08:26:11.967810Z] [debug] [pid:3081] no change: 31.0s[0m
[31m[2024-05-28T08:26:13.780825Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.81 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:26:13.780910Z] [debug] [pid:3081] no match: 31.0s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T08:26:15.613178Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.83 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:26:15.613257Z] [debug] [pid:3081] no match: 29.2s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T08:26:17.392971Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.78 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:26:17.393053Z] [debug] [pid:3081] no match: 27.3s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T08:26:22.609058Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 5.21 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:26:22.609168Z] [debug] [pid:3081] no match: 25.6s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T08:26:27.773189Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 5.16 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:26:27.773271Z] [debug] [pid:3081] no match: 20.3s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T08:26:33.031198Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 5.25 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:26:33.031284Z] [debug] [pid:3081] no match: 15.2s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T08:26:34.844324Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.81 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:26:34.844415Z] [debug] [pid:3081] no match: 9.9s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T08:26:36.666978Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.82 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:26:36.667069Z] [debug] [pid:3081] no match: 8.1s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T08:26:38.538291Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.87 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:26:38.538378Z] [debug] [pid:3081] no match: 6.3s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T08:26:40.364918Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.82 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:26:40.365002Z] [debug] [pid:3081] no match: 4.4s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[37m[2024-05-28T08:26:40.367282Z] [debug] [pid:3081] no change: 2.6s[0m
[31m[2024-05-28T08:26:42.159150Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.79 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:26:42.159243Z] [debug] [pid:3081] no match: 2.6s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T08:26:47.435905Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 5.27 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:26:47.436012Z] [debug] [pid:3081] no match: 0.8s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T08:26:52.711970Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 5.27 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:26:52.712073Z] [debug] [pid:3081] no match: -4.5s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[32m[2024-05-28T08:26:52.823212Z] [debug] [pid:2759] >>> testapi::_check_backend_response: match=autoyast-boot,autoyast-error,bios-boot,import-untrusted-gpg-key,linuxrc-install-fail,manual-intervention,nonexisting-package,nvidia-validation-failed,opensuse-welcome,package-notification,reboot-after-installation,scc-invalid-url,warning-pop-up timed out after 50 (check_screen)[0m
[2024-05-28T08:26:52.839067Z] [debug] [pid:2759] tests/autoyast/installation.pm:179 called installation::verify_timeout_and_check_screen -> tests/autoyast/installation.pm:103 called testapi::check_screen
[2024-05-28T08:26:52.839269Z] [debug] [pid:2759] <<< testapi::check_screen(mustmatch=[
    "bios-boot",
    "nonexisting-package",
    "reboot-after-installation",
    "linuxrc-install-fail",
    "scc-invalid-url",
    "warning-pop-up",
    "autoyast-boot",
    "package-notification",
    "nvidia-validation-failed",
    "import-untrusted-gpg-key",
    "autoyast-error",
    "manual-intervention",
    "opensuse-welcome"
  ], timeout=50)
[31m[2024-05-28T08:26:55.557371Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 2.71 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:26:55.557468Z] [debug] [pid:3081] no match: 49.9s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T08:26:57.392043Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.83 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:26:57.392132Z] [debug] [pid:3081] no match: 47.2s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T08:27:02.881289Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 5.49 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:27:02.881372Z] [debug] [pid:3081] no match: 45.4s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[37m[2024-05-28T08:27:02.881688Z] [debug] [pid:3081] considering VNC stalled, no update for 7.32 seconds[0m
[37m[2024-05-28T08:27:02.883169Z] [debug] [pid:3081] pointer type 1 0 1024 768 -257[0m
[37m[2024-05-28T08:27:02.883259Z] [debug] [pid:3081] led state 0 1 1 -261[0m
[37m[2024-05-28T08:27:02.885556Z] [debug] [pid:3081] no change: 39.9s[0m
[31m[2024-05-28T08:27:04.712334Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.83 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:27:04.712419Z] [debug] [pid:3081] no match: 39.9s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[37m[2024-05-28T08:27:04.715313Z] [debug] [pid:3081] no change: 38.1s[0m
[31m[2024-05-28T08:27:06.537113Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.82 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:27:06.537210Z] [debug] [pid:3081] no match: 38.1s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[37m[2024-05-28T08:27:06.542054Z] [debug] [pid:3081] no change: 36.2s[0m
[31m[2024-05-28T08:27:08.379862Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.84 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:27:08.379951Z] [debug] [pid:3081] no match: 36.2s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[37m[2024-05-28T08:27:08.382644Z] [debug] [pid:3081] no change: 34.4s[0m
[31m[2024-05-28T08:27:10.208593Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.83 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:27:10.208688Z] [debug] [pid:3081] no match: 34.4s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[37m[2024-05-28T08:27:10.211397Z] [debug] [pid:3081] no change: 32.6s[0m
[31m[2024-05-28T08:27:12.040795Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.83 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:27:12.040891Z] [debug] [pid:3081] no match: 32.6s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T08:27:17.365117Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 5.32 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:27:17.365226Z] [debug] [pid:3081] no match: 30.7s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T08:27:22.601635Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 5.23 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:27:22.601740Z] [debug] [pid:3081] no match: 25.4s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T08:27:27.812803Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 5.20 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:27:27.812888Z] [debug] [pid:3081] no match: 20.2s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T08:27:33.049590Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 5.23 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:27:33.049676Z] [debug] [pid:3081] no match: 15.0s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[37m[2024-05-28T08:27:33.054763Z] [debug] [pid:3081] no change: 9.7s[0m
[31m[2024-05-28T08:27:34.854530Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.80 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:27:34.854629Z] [debug] [pid:3081] no match: 9.7s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T08:27:36.659201Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.80 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:27:36.659287Z] [debug] [pid:3081] no match: 7.9s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[37m[2024-05-28T08:27:36.661902Z] [debug] [pid:3081] no change: 6.1s[0m
[31m[2024-05-28T08:27:38.451391Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.79 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:27:38.451478Z] [debug] [pid:3081] no match: 6.1s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[37m[2024-05-28T08:27:38.453989Z] [debug] [pid:3081] no change: 4.3s[0m
[31m[2024-05-28T08:27:40.249095Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.79 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:27:40.249188Z] [debug] [pid:3081] no match: 4.3s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[37m[2024-05-28T08:27:40.251646Z] [debug] [pid:3081] no change: 2.5s[0m
[31m[2024-05-28T08:27:42.065460Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.81 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:27:42.065552Z] [debug] [pid:3081] no match: 2.5s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T08:27:47.279688Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 5.21 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:27:47.279774Z] [debug] [pid:3081] no match: 0.7s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T08:27:52.629920Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 5.34 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:27:52.630012Z] [debug] [pid:3081] no match: -4.5s, best candidate: consoletest_finish-gnome-20191211 (0.23)[0m
[32m[2024-05-28T08:27:52.755755Z] [debug] [pid:2759] >>> testapi::_check_backend_response: match=autoyast-boot,autoyast-error,bios-boot,import-untrusted-gpg-key,linuxrc-install-fail,manual-intervention,nonexisting-package,nvidia-validation-failed,opensuse-welcome,package-notification,reboot-after-installation,scc-invalid-url,warning-pop-up timed out after 50 (check_screen)[0m
[2024-05-28T08:27:52.770437Z] [debug] [pid:2759] tests/autoyast/installation.pm:179 called installation::verify_timeout_and_check_screen -> tests/autoyast/installation.pm:103 called testapi::check_screen
[2024-05-28T08:27:52.770597Z] [debug] [pid:2759] <<< testapi::check_screen(mustmatch=[
    "bios-boot",
    "nonexisting-package",
    "reboot-after-installation",
    "linuxrc-install-fail",
    "scc-invalid-url",
    "warning-pop-up",
    "autoyast-boot",
    "package-notification",
    "nvidia-validation-failed",
    "import-untrusted-gpg-key",
    "autoyast-error",
    "manual-intervention",
    "opensuse-welcome"
  ], timeout=50)
[31m[2024-05-28T08:27:55.697498Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 2.92 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:27:55.697590Z] [debug] [pid:3081] no match: 49.9s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[32m[2024-05-28T08:27:57.584732Z] [debug] [pid:2759] >>> testapi::_handle_found_needle: found grub2-TW-virtio-20190331, similarity 1.00 @ 11/147[0m
[2024-05-28T08:27:57.585315Z] [debug] [pid:2759] tests/autoyast/installation.pm:181 called testapi::send_key
[2024-05-28T08:27:57.585446Z] [debug] [pid:2759] <<< testapi::send_key(key="ret", wait_screen_change=0)
[2024-05-28T08:27:57.853357Z] [debug] [pid:2759] tests/autoyast/installation.pm:345 called testapi::check_screen
[2024-05-28T08:27:57.853607Z] [debug] [pid:2759] <<< testapi::check_screen(mustmatch=[
    "bios-boot",
    "nonexisting-package",
    "reboot-after-installation",
    "linuxrc-install-fail",
    "scc-invalid-url",
    "warning-pop-up",
    "autoyast-boot",
    "package-notification",
    "nvidia-validation-failed",
    "import-untrusted-gpg-key",
    "autoyast-error",
    "manual-intervention",
    "opensuse-welcome"
  ], timeout=50)
[32m[2024-05-28T08:28:00.629748Z] [debug] [pid:2759] >>> testapi::_handle_found_needle: found grub2-TW-virtio-20190331, similarity 1.00 @ 11/147[0m
[2024-05-28T08:28:00.630497Z] [debug] [pid:2759] tests/autoyast/installation.pm:362 called installation::verify_timeout_and_check_screen -> tests/autoyast/installation.pm:103 called testapi::check_screen
[2024-05-28T08:28:00.630650Z] [debug] [pid:2759] <<< testapi::check_screen(mustmatch=[
    "reboot-after-installation",
    "autoyast-postinstall-error",
    "autoyast-boot",
    "unreachable-repo",
    "warning-pop-up",
    "inst-bootmenu",
    "lang_and_keyboard",
    "encrypted-disk-password-prompt",
    "autoyast-error",
    "opensuse-welcome"
  ], timeout=50)
[31m[2024-05-28T08:28:03.744217Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 3.11 seconds for 182 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:28:03.744300Z] [debug] [pid:3081] no match: 49.9s, best candidate: boot_encrypt-encrypted-disk-password-prompt-20221029 (0.29)[0m
[31m[2024-05-28T08:28:06.141514Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 2.39 seconds for 182 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:28:06.141605Z] [debug] [pid:3081] no match: 46.8s, best candidate: boot_encrypt-encrypted-disk-password-prompt-20221029 (0.29)[0m
[37m[2024-05-28T08:28:06.146200Z] [debug] [pid:3081] no change: 44.4s[0m
[31m[2024-05-28T08:28:08.541219Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 2.39 seconds for 182 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:28:08.541306Z] [debug] [pid:3081] no match: 44.4s, best candidate: boot_encrypt-encrypted-disk-password-prompt-20221029 (0.29)[0m
[37m[2024-05-28T08:28:08.544073Z] [debug] [pid:3081] no change: 42.0s[0m
[31m[2024-05-28T08:28:10.954201Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 2.41 seconds for 182 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:28:10.954303Z] [debug] [pid:3081] no match: 42.0s, best candidate: boot_encrypt-encrypted-disk-password-prompt-20221029 (0.29)[0m
[37m[2024-05-28T08:28:10.957177Z] [debug] [pid:3081] no change: 39.6s[0m
[31m[2024-05-28T08:28:13.367660Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 2.41 seconds for 182 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:28:13.367760Z] [debug] [pid:3081] no match: 39.6s, best candidate: boot_encrypt-encrypted-disk-password-prompt-20221029 (0.29)[0m
[32m[2024-05-28T08:28:15.607211Z] [debug] [pid:2759] >>> testapi::_handle_found_needle: found boot_encrypt-encrypted-disk-password-prompt-20200427, similarity 1.00 @ 372/317[0m
[1;34m[2024-05-28T08:28:15.649933Z] [debug] [pid:2759] ||| finished installation autoyast (runtime: 730 s)[0m
[1;34m[2024-05-28T08:28:15.657407Z] [debug] [pid:2759] ||| starting boot_encrypt tests/installation/boot_encrypt.pm[0m
[2024-05-28T08:28:15.658118Z] [debug] [pid:2759] tests/installation/boot_encrypt.pm:17 called utils::unlock_if_encrypted -> lib/utils.pm:360 called testapi::assert_screen
[2024-05-28T08:28:15.658232Z] [debug] [pid:2759] <<< testapi::assert_screen(mustmatch="encrypted-disk-password-prompt", timeout=200)
[32m[2024-05-28T08:28:15.859137Z] [debug] [pid:2759] >>> testapi::_handle_found_needle: found boot_encrypt-encrypted-disk-password-prompt-20200427, similarity 1.00 @ 372/317[0m
[2024-05-28T08:28:15.859439Z] [debug] [pid:2759] tests/installation/boot_encrypt.pm:17 called utils::unlock_if_encrypted -> lib/utils.pm:361 called testapi::type_password
[2024-05-28T08:28:15.859696Z] [debug] [pid:2759] <<< testapi::type_string(string="[masked]", max_interval=100, wait_screen_change=0, wait_still_screen=0, timeout=30, similarity_level=47)
[2024-05-28T08:28:17.108106Z] [debug] [pid:2759] tests/installation/boot_encrypt.pm:17 called utils::unlock_if_encrypted -> lib/utils.pm:364 called testapi::check_screen
[2024-05-28T08:28:17.108249Z] [debug] [pid:2759] <<< testapi::check_screen(mustmatch="encrypted_disk-typed_password", timeout=30)
[37m[2024-05-28T08:28:17.173204Z] [debug] [pid:3081] no match: 29.9s, best candidate: boot_encrypt-encrypted_disk-typed_password-tianocore-20230710 (0.29)[0m
[32m[2024-05-28T08:28:18.174467Z] [debug] [pid:2759] >>> testapi::_handle_found_needle: found boot_encrypt-encrypted_disk-typed_password-20200417, similarity 1.00 @ 350/286[0m
[2024-05-28T08:28:18.174627Z] [debug] [pid:2759] tests/installation/boot_encrypt.pm:17 called utils::unlock_if_encrypted -> lib/utils.pm:371 called testapi::send_key
[2024-05-28T08:28:18.174736Z] [debug] [pid:2759] <<< testapi::send_key(key="ret", wait_screen_change=0)
[2024-05-28T08:28:18.442761Z] [debug] [pid:2759] tests/installation/boot_encrypt.pm:17 called utils::unlock_if_encrypted -> lib/utils.pm:372 called testapi::wait_still_screen
[2024-05-28T08:28:18.443020Z] [debug] [pid:2759] <<< testapi::wait_still_screen(stilltime=15, timeout=30, similarity_level=47)
[32m[2024-05-28T08:28:48.744683Z] [debug] [pid:2759] >>> testapi::wait_still_screen: wait_still_screen timed out after 30.2471358776093 seconds, last detected similarity is 1000000[0m
[1;34m[2024-05-28T08:28:48.745071Z] [debug] [pid:2759] ||| finished boot_encrypt installation (runtime: 33 s)[0m
[1;34m[2024-05-28T08:28:48.746031Z] [debug] [pid:2759] ||| starting first_boot tests/installation/first_boot.pm[0m
[2024-05-28T08:28:48.746640Z] [debug] [pid:2759] tests/installation/first_boot.pm:23 called opensusebasetest::wait_boot_past_bootloader -> lib/opensusebasetest.pm:818 called testapi::check_screen
[2024-05-28T08:28:48.746769Z] [debug] [pid:2759] <<< testapi::check_screen(mustmatch=[
    "generic-desktop",
    "emergency-shell",
    "emergency-mode",
    "opensuse-welcome",
    "gnome-activities"
  ], timeout=30)
[31m[2024-05-28T08:28:51.701302Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 2.95 seconds for 122 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:28:51.701383Z] [debug] [pid:3081] no match: 29.9s, best candidate: application_starts_on_login-WRONG-XTERM-generic-desktop-20221129 (0.00)[0m
[37m[2024-05-28T08:28:51.703959Z] [debug] [pid:3081] no change: 27.0s[0m
[31m[2024-05-28T08:28:53.443207Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.74 seconds for 122 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:28:53.443306Z] [debug] [pid:3081] no match: 27.0s, best candidate: application_starts_on_login-WRONG-XTERM-generic-desktop-20221129 (0.00)[0m
[31m[2024-05-28T08:28:58.799250Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 5.35 seconds for 122 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:28:58.799335Z] [debug] [pid:3081] no match: 25.3s, best candidate: application_starts_on_login-WRONG-XTERM-generic-desktop-20221129 (0.00)[0m
[31m[2024-05-28T08:29:00.566880Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.76 seconds for 122 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:29:00.566969Z] [debug] [pid:3081] no match: 19.9s, best candidate: application_starts_on_login-WRONG-XTERM-generic-desktop-20221129 (0.00)[0m
[37m[2024-05-28T08:29:00.572198Z] [debug] [pid:3081] no change: 18.1s[0m
[31m[2024-05-28T08:29:02.330001Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.76 seconds for 122 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:29:02.330083Z] [debug] [pid:3081] no match: 18.1s, best candidate: application_starts_on_login-WRONG-XTERM-generic-desktop-20221129 (0.00)[0m
[37m[2024-05-28T08:29:02.335212Z] [debug] [pid:3081] no change: 16.4s[0m
[31m[2024-05-28T08:29:04.125619Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.79 seconds for 122 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:29:04.125701Z] [debug] [pid:3081] no match: 16.4s, best candidate: application_starts_on_login-WRONG-XTERM-generic-desktop-20221129 (0.00)[0m
[31m[2024-05-28T08:29:06.215635Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 2.08 seconds for 122 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:29:06.215723Z] [debug] [pid:3081] no match: 14.6s, best candidate: consoletest_finish-gnome-20191211 (0.22)[0m
[37m[2024-05-28T08:29:06.219369Z] [debug] [pid:3081] no change: 12.5s[0m
[31m[2024-05-28T08:29:08.303792Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 2.08 seconds for 122 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:29:08.303878Z] [debug] [pid:3081] no match: 12.5s, best candidate: consoletest_finish-gnome-20191211 (0.22)[0m
[31m[2024-05-28T08:29:24.073439Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 15.77 seconds for 122 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:29:24.073522Z] [debug] [pid:3081] no match: 10.4s, best candidate: consoletest_finish-gnome-20191211 (0.22)[0m
[31m[2024-05-28T08:29:24.076744Z] [warn] [pid:3081] !!! backend::baseclass::do_capture: There is some problem with your environment, we detected a stall for 15.7723350524902 seconds[0m
[31m[2024-05-28T08:29:29.387556Z] [warn] [pid:3081] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 5.31 seconds for 122 candidate needles - make your needles more specific[0m
[37m[2024-05-28T08:29:29.387640Z] [debug] [pid:3081] no match: -5.4s, best candidate: gnome-activities-leap154-20221223 (0.92)[0m
[32m[2024-05-28T08:29:29.514702Z] [debug] [pid:2759] >>> testapi::_check_backend_response: match=emergency-mode,emergency-shell,generic-desktop,gnome-activities,opensuse-welcome timed out after 30 (check_screen)[0m
[31m[2024-05-28T08:29:29.527664Z] [warn] [pid:2759] !!! testapi::_check_backend_response: stall detected during check_screen failure![0m
[2024-05-28T08:29:29.529422Z] [debug] [pid:2759] tests/installation/first_boot.pm:23 called opensusebasetest::wait_boot_past_bootloader -> lib/opensusebasetest.pm:818 called testapi::check_screen
[2024-05-28T08:29:29.529578Z] [debug] [pid:2759] <<< testapi::check_screen(mustmatch=[
    "generic-desktop",
    "emergency-shell",
    "emergency-mode",
    "opensuse-welcome",
    "gnome-activities"
  ], timeout=30)
[32m[2024-05-28T08:29:32.295052Z] [debug] [pid:2759] >>> testapi::_handle_found_needle: found opensuse-gnome-activities-20240321, similarity 1.00 @ 694/697[0m
[2024-05-28T08:29:32.295699Z] [debug] [pid:2759] tests/installation/first_boot.pm:23 called opensusebasetest::wait_boot_past_bootloader -> lib/opensusebasetest.pm:826 called testapi::send_key
[2024-05-28T08:29:32.295849Z] [debug] [pid:2759] <<< testapi::send_key(key="esc", wait_screen_change=0)
[2024-05-28T08:29:32.564112Z] [debug] [pid:2759] tests/installation/first_boot.pm:23 called opensusebasetest::wait_boot_past_bootloader -> lib/opensusebasetest.pm:832 called testapi::assert_screen
[2024-05-28T08:29:32.564360Z] [debug] [pid:2759] <<< testapi::assert_screen(mustmatch=[
    "generic-desktop",
    "emergency-shell",
    "emergency-mode",
    "opensuse-welcome"
  ], timeout=30)
[32m[2024-05-28T08:29:35.049790Z] [debug] [pid:2759] >>> testapi::_handle_found_needle: found opensuse-welcome-gnome-in-activites-20240514, similarity 1.00 @ 700/592[0m
[2024-05-28T08:29:35.050450Z] [debug] [pid:2759] tests/installation/first_boot.pm:23 called opensusebasetest::wait_boot_past_bootloader -> lib/opensusebasetest.pm:841 called testapi::mouse_hide
[2024-05-28T08:29:35.050562Z] [debug] [pid:2759] <<< testapi::mouse_hide(border_offset=1)
[37m[2024-05-28T08:29:35.051092Z] [debug] [pid:3081] mouse_move 1022, 766[0m
[37m[2024-05-28T08:29:35.051169Z] [debug] [pid:3081] send_pointer_event 0, 1022, 766, 1[0m
[1;34m[2024-05-28T08:29:35.051843Z] [debug] [pid:2759] ||| finished first_boot installation (runtime: 47 s)[0m
[37m[2024-05-28T08:29:35.054230Z] [debug] [pid:2759] Creating a VM snapshot lastgood[0m
[37m[2024-05-28T08:29:35.054757Z] [debug] [pid:3081] EVENT {"data":{"path":"\/machine\/peripheral-anon\/device[3]\/virtio-backend"},"event":"NIC_RX_FILTER_CHANGED","timestamp":{"microseconds":203807,"seconds":1716884182}}[0m
[37m[2024-05-28T08:29:35.054947Z] [debug] [pid:3081] EVENT {"data":{"client":{"family":"ipv4","host":"127.0.0.1","service":"53856","websocket":false},"server":{"auth":"none","family":"ipv4","host":"0.0.0.0","service":"6020","websocket":false}},"event":"VNC_DISCONNECTED","timestamp":{"microseconds":881882,"seconds":1716884822}}[0m
[37m[2024-05-28T08:29:35.055114Z] [debug] [pid:3081] EVENT {"data":{"client":{"family":"ipv4","host":"127.0.0.1","service":"35564","websocket":false},"server":{"auth":"none","family":"ipv4","host":"0.0.0.0","service":"6020","websocket":false}},"event":"VNC_CONNECTED","timestamp":{"microseconds":882125,"seconds":1716884822}}[0m
[37m[2024-05-28T08:29:35.055267Z] [debug] [pid:3081] EVENT {"data":{"client":{"family":"ipv4","host":"127.0.0.1","service":"35564","websocket":false},"server":{"auth":"none","family":"ipv4","host":"0.0.0.0","service":"6020","websocket":false}},"event":"VNC_INITIALIZED","timestamp":{"microseconds":882808,"seconds":1716884822}}[0m
[37m[2024-05-28T08:29:35.055407Z] [debug] [pid:3081] EVENT {"data":{"guest":true,"reason":"guest-reset"},"event":"RESET","timestamp":{"microseconds":274319,"seconds":1716884867}}[0m
[37m[2024-05-28T08:29:35.055528Z] [debug] [pid:3081] EVENT {"data":{"guest":true,"reason":"guest-reset"},"event":"RESET","timestamp":{"microseconds":279601,"seconds":1716884867}}[0m
[37m[2024-05-28T08:29:35.055678Z] [debug] [pid:3081] Saving snapshot (Current VM state is running)[0m
[37m[2024-05-28T08:29:35.075906Z] [debug] [pid:3081] EVENT {"event":"STOP","timestamp":{"microseconds":75676,"seconds":1716884975}}[0m
[37m[2024-05-28T08:29:35.081831Z] [debug] [pid:3081] blockdev-snapshot-sync({'arguments' => {'format' => 'qcow2','node-name' => 'hd0','snapshot-file' => '/var/lib/openqa/pool/30/raid/hd0-overlay1','snapshot-node-name' => 'hd0-overlay1'},'execute' => 'blockdev-snapshot-sync'}) -> {'return' => {}}[0m
[37m[2024-05-28T08:29:35.086968Z] [debug] [pid:3081] blockdev-snapshot-sync({'arguments' => {'format' => 'qcow2','node-name' => 'hd1','snapshot-file' => '/var/lib/openqa/pool/30/raid/hd1-overlay1','snapshot-node-name' => 'hd1-overlay1'},'execute' => 'blockdev-snapshot-sync'}) -> {'return' => {}}[0m
[37m[2024-05-28T08:29:35.093274Z] [debug] [pid:3081] blockdev-snapshot-sync({'arguments' => {'format' => 'qcow2','node-name' => 'hd2','snapshot-file' => '/var/lib/openqa/pool/30/raid/hd2-overlay1','snapshot-node-name' => 'hd2-overlay1'},'execute' => 'blockdev-snapshot-sync'}) -> {'return' => {}}[0m
[37m[2024-05-28T08:29:35.098156Z] [debug] [pid:3081] blockdev-snapshot-sync({'arguments' => {'format' => 'qcow2','node-name' => 'hd3','snapshot-file' => '/var/lib/openqa/pool/30/raid/hd3-overlay1','snapshot-node-name' => 'hd3-overlay1'},'execute' => 'blockdev-snapshot-sync'}) -> {'return' => {}}[0m
[37m[2024-05-28T08:29:35.101985Z] [debug] [pid:3081] blockdev-snapshot-sync({'arguments' => {'format' => 'qcow2','node-name' => 'cd0-overlay0','snapshot-file' => '/var/lib/openqa/pool/30/raid/cd0-overlay1','snapshot-node-name' => 'cd0-overlay1'},'execute' => 'blockdev-snapshot-sync'}) -> {'return' => {}}[0m
[37m[2024-05-28T08:29:35.104926Z] [debug] [pid:3081] EVENT {"data":{"status":"setup"},"event":"MIGRATION","timestamp":{"microseconds":104834,"seconds":1716884975}}[0m
[37m[2024-05-28T08:29:35.605236Z] [debug] [pid:3081] EVENT {"data":{"pass":1},"event":"MIGRATION_PASS","timestamp":{"microseconds":120497,"seconds":1716884975}}[0m
[37m[2024-05-28T08:29:35.605333Z] [debug] [pid:3081] EVENT {"data":{"status":"active"},"event":"MIGRATION","timestamp":{"microseconds":120625,"seconds":1716884975}}[0m
[37m[2024-05-28T08:29:35.605503Z] [debug] [pid:3081] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T08:29:35.605562Z] [debug] [pid:3081] Migrating remaining bytes:   	1613242368[0m
[37m[2024-05-28T08:29:36.106255Z] [debug] [pid:3081] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T08:29:36.106335Z] [debug] [pid:3081] Migrating remaining bytes:   	1593475072[0m
[37m[2024-05-28T08:29:36.607105Z] [debug] [pid:3081] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T08:29:36.607205Z] [debug] [pid:3081] Migrating remaining bytes:   	1571004416[0m
[37m[2024-05-28T08:29:37.107965Z] [debug] [pid:3081] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T08:29:37.108045Z] [debug] [pid:3081] Migrating remaining bytes:   	1543114752[0m
[37m[2024-05-28T08:29:37.608717Z] [debug] [pid:3081] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T08:29:37.608785Z] [debug] [pid:3081] Migrating remaining bytes:   	1522556928[0m
[37m[2024-05-28T08:29:38.109409Z] [debug] [pid:3081] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T08:29:38.109478Z] [debug] [pid:3081] Migrating remaining bytes:   	1502978048[0m
[37m[2024-05-28T08:29:38.610094Z] [debug] [pid:3081] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T08:29:38.610162Z] [debug] [pid:3081] Migrating remaining bytes:   	1482452992[0m
[37m[2024-05-28T08:29:39.110813Z] [debug] [pid:3081] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T08:29:39.110879Z] [debug] [pid:3081] Migrating remaining bytes:   	1464819712[0m
[37m[2024-05-28T08:29:39.611483Z] [debug] [pid:3081] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T08:29:39.611556Z] [debug] [pid:3081] Migrating remaining bytes:   	1448308736[0m
[37m[2024-05-28T08:29:40.112208Z] [debug] [pid:3081] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T08:29:40.112288Z] [debug] [pid:3081] Migrating remaining bytes:   	1434185728[0m
[37m[2024-05-28T08:29:40.612893Z] [debug] [pid:3081] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T08:29:40.612956Z] [debug] [pid:3081] Migrating remaining bytes:   	1418969088[0m
[37m[2024-05-28T08:29:41.113506Z] [debug] [pid:3081] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T08:29:41.113570Z] [debug] [pid:3081] Migrating remaining bytes:   	1402712064[0m
[37m[2024-05-28T08:29:41.614216Z] [debug] [pid:3081] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T08:29:41.614286Z] [debug] [pid:3081] Migrating remaining bytes:   	1386467328[0m
[37m[2024-05-28T08:29:42.114801Z] [debug] [pid:3081] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T08:29:42.114864Z] [debug] [pid:3081] Migrating remaining bytes:   	1369620480[0m
[37m[2024-05-28T08:29:42.615398Z] [debug] [pid:3081] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T08:29:42.615462Z] [debug] [pid:3081] Migrating remaining bytes:   	1352458240[0m
[37m[2024-05-28T08:29:43.116033Z] [debug] [pid:3081] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T08:29:43.116107Z] [debug] [pid:3081] Migrating remaining bytes:   	1335300096[0m
[37m[2024-05-28T08:29:43.616707Z] [debug] [pid:3081] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T08:29:43.616773Z] [debug] [pid:3081] Migrating remaining bytes:   	1316945920[0m
[37m[2024-05-28T08:29:44.117338Z] [debug] [pid:3081] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T08:29:44.117403Z] [debug] [pid:3081] Migrating remaining bytes:   	1301102592[0m
[37m[2024-05-28T08:29:44.618014Z] [debug] [pid:3081] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T08:29:44.618077Z] [debug] [pid:3081] Migrating remaining bytes:   	1282015232[0m
[37m[2024-05-28T08:29:45.118713Z] [debug] [pid:3081] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T08:29:45.118780Z] [debug] [pid:3081] Migrating remaining bytes:   	1261101056[0m
[37m[2024-05-28T08:29:45.619431Z] [debug] [pid:3081] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T08:29:45.619492Z] [debug] [pid:3081] Migrating remaining bytes:   	1242329088[0m
[37m[2024-05-28T08:29:46.120053Z] [debug] [pid:3081] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T08:29:46.120117Z] [debug] [pid:3081] Migrating remaining bytes:   	1226600448[0m
[37m[2024-05-28T08:29:46.620722Z] [debug] [pid:3081] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T08:29:46.620785Z] [debug] [pid:3081] Migrating remaining bytes:   	1211559936[0m
[37m[2024-05-28T08:29:47.121381Z] [debug] [pid:3081] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T08:29:47.121446Z] [debug] [pid:3081] Migrating remaining bytes:   	1195134976[0m
[37m[2024-05-28T08:29:47.622293Z] [debug] [pid:3081] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T08:29:47.622392Z] [debug] [pid:3081] Migrating remaining bytes:   	1179295744[0m
[37m[2024-05-28T08:29:48.123292Z] [debug] [pid:3081] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T08:29:48.123398Z] [debug] [pid:3081] Migrating remaining bytes:   	1163100160[0m
[37m[2024-05-28T08:29:48.624024Z] [debug] [pid:3081] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T08:29:48.624090Z] [debug] [pid:3081] Migrating remaining bytes:   	1146097664[0m
[37m[2024-05-28T08:29:49.124790Z] [debug] [pid:3081] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T08:29:49.124863Z] [debug] [pid:3081] Migrating remaining bytes:   	1128935424[0m
[37m[2024-05-28T08:29:49.625450Z] [debug] [pid:3081] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T08:29:49.625507Z] [debug] [pid:3081] Migrating remaining bytes:   	1111879680[0m
[37m[2024-05-28T08:29:50.126378Z] [debug] [pid:3081] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T08:29:50.126471Z] [debug] [pid:3081] Migrating remaining bytes:   	1095200768[0m
[37m[2024-05-28T08:29:50.627434Z] [debug] [pid:3081] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T08:29:50.627537Z] [debug] [pid:3081] Migrating remaining bytes:   	1077731328[0m
[37m[2024-05-28T08:29:51.128215Z] [debug] [pid:3081] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T08:29:51.128279Z] [debug] [pid:3081] Migrating remaining bytes:   	1063514112[0m
[37m[2024-05-28T08:29:51.629172Z] [debug] [pid:3081] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T08:29:51.629270Z] [debug] [pid:3081] Migrating remaining bytes:   	1047437312[0m
[37m[2024-05-28T08:29:52.130199Z] [debug] [pid:3081] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T08:29:52.130303Z] [debug] [pid:3081] Migrating remaining bytes:   	1027067904[0m
[37m[2024-05-28T08:29:52.631154Z] [debug] [pid:3081] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T08:29:52.631257Z] [debug] [pid:3081] Migrating remaining bytes:   	1007570944[0m
[37m[2024-05-28T08:29:53.132157Z] [debug] [pid:3081] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T08:29:53.132260Z] [debug] [pid:3081] Migrating remaining bytes:   	989245440[0m
[37m[2024-05-28T08:29:53.632864Z] [debug] [pid:3081] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T08:29:53.632927Z] [debug] [pid:3081] Migrating remaining bytes:   	971919360[0m
[37m[2024-05-28T08:29:54.133609Z] [debug] [pid:3081] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T08:29:54.133703Z] [debug] [pid:3081] Migrating remaining bytes:   	954806272[0m
[37m[2024-05-28T08:29:54.634373Z] [debug] [pid:3081] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T08:29:54.634441Z] [debug] [pid:3081] Migrating remaining bytes:   	937902080[0m
[37m[2024-05-28T08:29:55.134956Z] [debug] [pid:3081] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T08:29:55.135025Z] [debug] [pid:3081] Migrating remaining bytes:   	921624576[0m
[37m[2024-05-28T08:29:55.635711Z] [debug] [pid:3081] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T08:29:55.635786Z] [debug] [pid:3081] Migrating remaining bytes:   	904658944[0m
[37m[2024-05-28T08:29:56.136451Z] [debug] [pid:3081] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T08:29:56.136519Z] [debug] [pid:3081] Migrating remaining bytes:   	889806848[0m
[37m[2024-05-28T08:29:56.637152Z] [debug] [pid:3081] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T08:29:56.637212Z] [debug] [pid:3081] Migrating remaining bytes:   	873979904[0m
[37m[2024-05-28T08:29:57.137639Z] [debug] [pid:3081] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T08:29:57.137699Z] [debug] [pid:3081] Migrating remaining bytes:   	858501120[0m
[37m[2024-05-28T08:29:57.638465Z] [debug] [pid:3081] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T08:29:57.638569Z] [debug] [pid:3081] Migrating remaining bytes:   	841363456[0m
[37m[2024-05-28T08:29:58.139317Z] [debug] [pid:3081] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T08:29:58.139399Z] [debug] [pid:3081] Migrating remaining bytes:   	823324672[0m
[37m[2024-05-28T08:29:58.640072Z] [debug] [pid:3081] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T08:29:58.640136Z] [debug] [pid:3081] Migrating remaining bytes:   	807165952[0m
[37m[2024-05-28T08:29:59.141067Z] [debug] [pid:3081] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T08:29:59.141142Z] [debug] [pid:3081] Migrating remaining bytes:   	789065728[0m
[37m[2024-05-28T08:29:59.641826Z] [debug] [pid:3081] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T08:29:59.641898Z] [debug] [pid:3081] Migrating remaining bytes:   	771977216[0m
[37m[2024-05-28T08:30:00.142621Z] [debug] [pid:3081] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T08:30:00.142705Z] [debug] [pid:3081] Migrating remaining bytes:   	756199424[0m
[37m[2024-05-28T08:30:00.643304Z] [debug] [pid:3081] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T08:30:00.643373Z] [debug] [pid:3081] Migrating remaining bytes:   	738865152[0m
[37m[2024-05-28T08:30:01.144034Z] [debug] [pid:3081] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T08:30:01.144105Z] [debug] [pid:3081] Migrating remaining bytes:   	712769536[0m
[37m[2024-05-28T08:30:01.644743Z] [debug] [pid:3081] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T08:30:01.644814Z] [debug] [pid:3081] Migrating remaining bytes:   	697946112[0m
[37m[2024-05-28T08:30:02.145475Z] [debug] [pid:3081] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T08:30:02.145605Z] [debug] [pid:3081] Migrating remaining bytes:   	682496000[0m
[37m[2024-05-28T08:30:02.646269Z] [debug] [pid:3081] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T08:30:02.646340Z] [debug] [pid:3081] Migrating remaining bytes:   	667582464[0m
[37m[2024-05-28T08:30:03.146989Z] [debug] [pid:3081] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T08:30:03.147056Z] [debug] [pid:3081] Migrating remaining bytes:   	651481088[0m
[37m[2024-05-28T08:30:03.647742Z] [debug] [pid:3081] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T08:30:03.647809Z] [debug] [pid:3081] Migrating remaining bytes:   	635224064[0m
[37m[2024-05-28T08:30:04.148704Z] [debug] [pid:3081] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T08:30:04.148802Z] [debug] [pid:3081] Migrating remaining bytes:   	618172416[0m
[37m[2024-05-28T08:30:04.649662Z] [debug] [pid:3081] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T08:30:04.649764Z] [debug] [pid:3081] Migrating remaining bytes:   	601399296[0m
[37m[2024-05-28T08:30:05.150507Z] [debug] [pid:3081] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T08:30:05.150606Z] [debug] [pid:3081] Migrating remaining bytes:   	585371648[0m
[37m[2024-05-28T08:30:05.651232Z] [debug] [pid:3081] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T08:30:05.651301Z] [debug] [pid:3081] Migrating remaining bytes:   	565108736[0m
[37m[2024-05-28T08:30:06.152206Z] [debug] [pid:3081] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T08:30:06.152277Z] [debug] [pid:3081] Migrating remaining bytes:   	548208640[0m
[37m[2024-05-28T08:30:06.653143Z] [debug] [pid:3081] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T08:30:06.653248Z] [debug] [pid:3081] Migrating remaining bytes:   	528674816[0m
[37m[2024-05-28T08:30:07.154110Z] [debug] [pid:3081] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T08:30:07.154213Z] [debug] [pid:3081] Migrating remaining bytes:   	510447616[0m
[37m[2024-05-28T08:30:07.655104Z] [debug] [pid:3081] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T08:30:07.655182Z] [debug] [pid:3081] Migrating remaining bytes:   	493391872[0m
[37m[2024-05-28T08:30:08.155810Z] [debug] [pid:3081] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T08:30:08.155878Z] [debug] [pid:3081] Migrating remaining bytes:   	476897280[0m
[37m[2024-05-28T08:30:08.656818Z] [debug] [pid:3081] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T08:30:08.656913Z] [debug] [pid:3081] Migrating remaining bytes:   	458211328[0m
[37m[2024-05-28T08:30:09.157857Z] [debug] [pid:3081] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T08:30:09.157953Z] [debug] [pid:3081] Migrating remaining bytes:   	439107584[0m
[37m[2024-05-28T08:30:09.658588Z] [debug] [pid:3081] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T08:30:09.658654Z] [debug] [pid:3081] Migrating remaining bytes:   	422117376[0m
[37m[2024-05-28T08:30:10.159249Z] [debug] [pid:3081] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T08:30:10.159323Z] [debug] [pid:3081] Migrating remaining bytes:   	406294528[0m
[37m[2024-05-28T08:30:10.660193Z] [debug] [pid:3081] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T08:30:10.660317Z] [debug] [pid:3081] Migrating remaining bytes:   	389365760[0m
[37m[2024-05-28T08:30:11.161277Z] [debug] [pid:3081] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T08:30:11.161379Z] [debug] [pid:3081] Migrating remaining bytes:   	367951872[0m
[37m[2024-05-28T08:30:11.662047Z] [debug] [pid:3081] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T08:30:11.662116Z] [debug] [pid:3081] Migrating remaining bytes:   	346075136[0m
[37m[2024-05-28T08:30:12.162773Z] [debug] [pid:3081] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T08:30:12.162840Z] [debug] [pid:3081] Migrating remaining bytes:   	327667712[0m
[37m[2024-05-28T08:30:12.663714Z] [debug] [pid:3081] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T08:30:12.663819Z] [debug] [pid:3081] Migrating remaining bytes:   	307814400[0m
[37m[2024-05-28T08:30:13.164515Z] [debug] [pid:3081] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T08:30:13.164584Z] [debug] [pid:3081] Migrating remaining bytes:   	282857472[0m
[37m[2024-05-28T08:30:13.665218Z] [debug] [pid:3081] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T08:30:13.665273Z] [debug] [pid:3081] Migrating remaining bytes:   	257794048[0m
[37m[2024-05-28T08:30:14.165800Z] [debug] [pid:3081] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T08:30:14.165861Z] [debug] [pid:3081] Migrating remaining bytes:   	240680960[0m
[37m[2024-05-28T08:30:14.666449Z] [debug] [pid:3081] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T08:30:14.666514Z] [debug] [pid:3081] Migrating remaining bytes:   	222203904[0m
[37m[2024-05-28T08:30:15.167061Z] [debug] [pid:3081] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T08:30:15.167131Z] [debug] [pid:3081] Migrating remaining bytes:   	206209024[0m
[37m[2024-05-28T08:30:15.667772Z] [debug] [pid:3081] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T08:30:15.667856Z] [debug] [pid:3081] Migrating remaining bytes:   	188522496[0m
[37m[2024-05-28T08:30:16.168401Z] [debug] [pid:3081] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T08:30:16.168462Z] [debug] [pid:3081] Migrating remaining bytes:   	172322816[0m
[37m[2024-05-28T08:30:16.669274Z] [debug] [pid:3081] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T08:30:16.669366Z] [debug] [pid:3081] Migrating remaining bytes:   	152973312[0m
[37m[2024-05-28T08:30:17.169992Z] [debug] [pid:3081] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T08:30:17.170057Z] [debug] [pid:3081] Migrating remaining bytes:   	132005888[0m
[37m[2024-05-28T08:30:17.670633Z] [debug] [pid:3081] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T08:30:17.670697Z] [debug] [pid:3081] Migrating remaining bytes:   	110604288[0m
[37m[2024-05-28T08:30:18.171207Z] [debug] [pid:3081] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T08:30:18.171266Z] [debug] [pid:3081] Migrating remaining bytes:   	88674304[0m
[37m[2024-05-28T08:30:18.671828Z] [debug] [pid:3081] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T08:30:18.671891Z] [debug] [pid:3081] Migrating remaining bytes:   	26734592[0m
[37m[2024-05-28T08:30:19.172323Z] [debug] [pid:3081] EVENT {"data":{"pass":2},"event":"MIGRATION_PASS","timestamp":{"microseconds":921737,"seconds":1716885018}}[0m
[37m[2024-05-28T08:30:19.172498Z] [debug] [pid:3081] EVENT {"data":{"pass":3},"event":"MIGRATION_PASS","timestamp":{"microseconds":978449,"seconds":1716885018}}[0m
[37m[2024-05-28T08:30:19.172631Z] [debug] [pid:3081] EVENT {"data":{"pass":4},"event":"MIGRATION_PASS","timestamp":{"microseconds":978686,"seconds":1716885018}}[0m
[37m[2024-05-28T08:30:19.172772Z] [debug] [pid:3081] EVENT {"data":{"status":"completed"},"event":"MIGRATION","timestamp":{"microseconds":984249,"seconds":1716885018}}[0m
[37m[2024-05-28T08:30:19.172965Z] [debug] [pid:3081] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T08:30:19.173042Z] [debug] [pid:3081] Migrating remaining bytes:   	0[0m
[37m[2024-05-28T08:30:19.173574Z] [debug] [pid:3081] Snapshot complete[0m
[37m[2024-05-28T08:30:20.510958Z] [debug] [pid:3081] EVENT {"event":"RESUME","timestamp":{"microseconds":510721,"seconds":1716885020}}[0m
[1;34m[2024-05-28T08:30:20.558401Z] [debug] [pid:2759] ||| starting console tests/autoyast/console.pm[0m
[37m[2024-05-28T08:30:20.560610Z] [debug] [pid:3081] QEMU: Formatting '/var/lib/openqa/pool/30/raid/hd0-overlay1', fmt=qcow2 cluster_size=65536 extended_l2=off compression_type=zlib size=21474836480 backing_file=/var/lib/openqa/pool/30/raid/hd0 backing_fmt=qcow2 lazy_refcounts=off refcount_bits=16[0m
[37m[2024-05-28T08:30:20.560682Z] [debug] [pid:3081] QEMU: Formatting '/var/lib/openqa/pool/30/raid/hd1-overlay1', fmt=qcow2 cluster_size=65536 extended_l2=off compression_type=zlib size=21474836480 backing_file=/var/lib/openqa/pool/30/raid/hd1 backing_fmt=qcow2 lazy_refcounts=off refcount_bits=16[0m
[37m[2024-05-28T08:30:20.560735Z] [debug] [pid:3081] QEMU: Formatting '/var/lib/openqa/pool/30/raid/hd2-overlay1', fmt=qcow2 cluster_size=65536 extended_l2=off compression_type=zlib size=21474836480 backing_file=/var/lib/openqa/pool/30/raid/hd2 backing_fmt=qcow2 lazy_refcounts=off refcount_bits=16[0m
[37m[2024-05-28T08:30:20.560783Z] [debug] [pid:3081] QEMU: Formatting '/var/lib/openqa/pool/30/raid/hd3-overlay1', fmt=qcow2 cluster_size=65536 extended_l2=off compression_type=zlib size=21474836480 backing_file=/var/lib/openqa/pool/30/raid/hd3 backing_fmt=qcow2 lazy_refcounts=off refcount_bits=16[0m
[37m[2024-05-28T08:30:20.560820Z] [debug] [pid:3081] QEMU: Formatting '/var/lib/openqa/pool/30/raid[0m
[37m[2024-05-28T08:30:20.561160Z] [debug] [pid:3081] QEMU: /cd0-overlay1', fmt=qcow2 cluster_size=65536 extended_l2=off compression_type=zlib size=4497342464 backing_file=/var/lib/openqa/pool/30/raid/cd0-overlay0 backing_fmt=qcow2 lazy_refcounts=off refcount_bits=16[0m
[2024-05-28T08:30:20.561927Z] [debug] [pid:2759] tests/autoyast/console.pm:22 called testapi::select_console
[2024-05-28T08:30:20.562058Z] [debug] [pid:2759] <<< testapi::select_console(testapi_console="root-console")
[37m[2024-05-28T08:30:20.969655Z] [debug] [pid:2759] activate_console, console: root-console, type: console[0m
[2024-05-28T08:30:20.969956Z] [debug] [pid:2759] tests/autoyast/console.pm:22 called testapi::select_console -> lib/susedistribution.pm:857 called testapi::wait_still_screen
[2024-05-28T08:30:20.970103Z] [debug] [pid:2759] <<< testapi::wait_still_screen(stilltime=1, timeout=30, similarity_level=47)
[32m[2024-05-28T08:30:22.568679Z] [debug] [pid:2759] >>> testapi::wait_still_screen: detected same image for 1 seconds (1.59362006187439 s elapsed), last detected similarity is 1000000[0m
[2024-05-28T08:30:22.568961Z] [debug] [pid:2759] tests/autoyast/console.pm:22 called testapi::select_console -> lib/susedistribution.pm:862 called testapi::assert_screen
[2024-05-28T08:30:22.569180Z] [debug] [pid:2759] <<< testapi::assert_screen(mustmatch=[
    "tty6-selected",
    "text-logged-in-root"
  ], timeout=60)
[32m[2024-05-28T08:30:22.674226Z] [debug] [pid:2759] >>> testapi::_handle_found_needle: found login-prompt-centos-20210810, similarity 1.00 @ 63/98[0m
[2024-05-28T08:30:22.674950Z] [debug] [pid:2759] tests/autoyast/console.pm:22 called testapi::select_console -> lib/susedistribution.pm:864 called testapi::enter_cmd
[2024-05-28T08:30:22.675098Z] [debug] [pid:2759] <<< testapi::type_string(string="root\n", max_interval=250, wait_screen_change=0, wait_still_screen=0, timeout=30, similarity_level=47)
[2024-05-28T08:30:22.844826Z] [debug] [pid:2759] tests/autoyast/console.pm:22 called testapi::select_console -> lib/susedistribution.pm:865 called susedistribution::handle_password_prompt -> lib/susedistribution.pm:70 called testapi::assert_screen
[2024-05-28T08:30:22.844986Z] [debug] [pid:2759] <<< testapi::assert_screen(mustmatch="password-prompt", timeout=60)
[32m[2024-05-28T08:30:23.702258Z] [debug] [pid:2759] >>> testapi::_handle_found_needle: found password-prompt-20160812, similarity 1.00 @ 0/112[0m
[2024-05-28T08:30:23.702433Z] [debug] [pid:2759] tests/autoyast/console.pm:22 called testapi::select_console -> lib/susedistribution.pm:865 called susedistribution::handle_password_prompt -> lib/susedistribution.pm:79 called testapi::type_password
[2024-05-28T08:30:23.702584Z] [debug] [pid:2759] <<< testapi::type_string(string="[masked]", max_interval=100, wait_screen_change=0, wait_still_screen=0, timeout=30, similarity_level=47)
[2024-05-28T08:30:24.908122Z] [debug] [pid:2759] tests/autoyast/console.pm:22 called testapi::select_console -> lib/susedistribution.pm:865 called susedistribution::handle_password_prompt -> lib/susedistribution.pm:81 called testapi::send_key
[2024-05-28T08:30:24.908353Z] [debug] [pid:2759] <<< testapi::send_key(key="ret", wait_screen_change=0)
[2024-05-28T08:30:25.176372Z] [debug] [pid:2759] tests/autoyast/console.pm:22 called testapi::select_console -> lib/susedistribution.pm:876 called testapi::assert_screen
[2024-05-28T08:30:25.176552Z] [debug] [pid:2759] <<< testapi::assert_screen(mustmatch="text-logged-in-root", timeout=60)
[37m[2024-05-28T08:30:25.188572Z] [debug] [pid:3081] no match: 59.9s, best candidate: text-logged-in-root-20170627 (0.78)[0m
[32m[2024-05-28T08:30:26.229811Z] [debug] [pid:2759] >>> testapi::_handle_found_needle: found text-logged-in-root-20151204, similarity 1.00 @ 55/144[0m
[2024-05-28T08:30:26.229993Z] [debug] [pid:2759] tests/autoyast/console.pm:22 called testapi::select_console -> lib/susedistribution.pm:879 called testapi::assert_screen
[2024-05-28T08:30:26.230090Z] [debug] [pid:2759] <<< testapi::assert_screen(mustmatch="root-console", timeout=30)
[32m[2024-05-28T08:30:27.251734Z] [debug] [pid:2759] >>> testapi::_handle_found_needle: found root-console-20180724, similarity 1.00 @ 80/144[0m
[2024-05-28T08:30:27.252040Z] [debug] [pid:2759] tests/autoyast/console.pm:22 called testapi::select_console -> lib/susedistribution.pm:933 called distribution::script_run
[2024-05-28T08:30:27.252226Z] [debug] [pid:2759] <<< testapi::type_string(string="setterm -blank 0", max_interval=250, wait_screen_change=0, wait_still_screen=0, timeout=30, similarity_level=47)
[2024-05-28T08:30:27.792614Z] [debug] [pid:2759] tests/autoyast/console.pm:22 called testapi::select_console -> lib/susedistribution.pm:933 called distribution::script_run
[2024-05-28T08:30:27.792882Z] [debug] [pid:2759] <<< testapi::type_string(string="; echo YpuUt-\$?- > /dev/ttyS0\n", max_interval=250, wait_screen_change=0, wait_still_screen=0, timeout=30, similarity_level=47)
[2024-05-28T08:30:28.906824Z] [debug] [pid:2759] tests/autoyast/console.pm:22 called testapi::select_console -> lib/susedistribution.pm:933 called distribution::script_run
[2024-05-28T08:30:28.907128Z] [debug] [pid:2759] <<< testapi::wait_serial(buffer_size=undef, timeout=30, expect_not_found=0, record_output=undef, regexp=qr/YpuUt-\d+-/u, no_regex=0, quiet=undef)
[32m[2024-05-28T08:30:29.950521Z] [debug] [pid:2759] >>> testapi::wait_serial: (?^u:YpuUt-\d+-): ok[0m
[2024-05-28T08:30:29.950775Z] [debug] [pid:2759] tests/autoyast/console.pm:22 called testapi::select_console -> lib/susedistribution.pm:997 called testapi::assert_screen
[2024-05-28T08:30:29.950892Z] [debug] [pid:2759] <<< testapi::assert_screen(mustmatch="root-console", no_wait=1, timeout=30)
[32m[2024-05-28T08:30:30.007678Z] [debug] [pid:2759] >>> testapi::_handle_found_needle: found root-console-20180724, similarity 1.00 @ 80/160[0m
[1;34m[2024-05-28T08:30:30.049351Z] [debug] [pid:2759] ||| finished console autoyast (runtime: 10 s)[0m
[1;34m[2024-05-28T08:30:30.050423Z] [debug] [pid:2759] ||| starting clone tests/autoyast/clone.pm[0m
[2024-05-28T08:30:30.050958Z] [debug] [pid:2759] tests/autoyast/clone.pm:20 called testapi::assert_script_run
[2024-05-28T08:30:30.051104Z] [debug] [pid:2759] <<< testapi::assert_script_run(cmd="rm -f /root/autoinst.xml", timeout=90, fail_message="", quiet=undef)
[2024-05-28T08:30:30.051226Z] [debug] [pid:2759] tests/autoyast/clone.pm:20 called testapi::assert_script_run
[2024-05-28T08:30:30.051356Z] [debug] [pid:2759] <<< testapi::type_string(string="rm -f /root/autoinst.xml", max_interval=250, wait_screen_change=0, wait_still_screen=0, timeout=30, similarity_level=47)
[2024-05-28T08:30:30.859442Z] [debug] [pid:2759] tests/autoyast/clone.pm:20 called testapi::assert_script_run
[2024-05-28T08:30:30.859646Z] [debug] [pid:2759] <<< testapi::type_string(string="; echo zQ81W-\$?- > /dev/ttyS0\n", max_interval=250, wait_screen_change=0, wait_still_screen=0, timeout=30, similarity_level=47)
[2024-05-28T08:30:31.971780Z] [debug] [pid:2759] tests/autoyast/clone.pm:20 called testapi::assert_script_run
[2024-05-28T08:30:31.972017Z] [debug] [pid:2759] <<< testapi::wait_serial(no_regex=0, quiet=undef, regexp=qr/zQ81W-\d+-/u, expect_not_found=0, record_output=undef, timeout=90, buffer_size=undef)
[32m[2024-05-28T08:30:33.015863Z] [debug] [pid:2759] >>> testapi::wait_serial: (?^u:zQ81W-\d+-): ok[0m
Odd number of elements in hash assignment at opensuse/lib/utils.pm line 579.
	utils::zypper_call("in autoyast2", 300) called at opensuse/tests/autoyast/clone.pm line 21
	clone::run(clone=HASH(0x561fdaf0e700)) called at /usr/lib/os-autoinst/basetest.pm line 352
	eval {...} called at /usr/lib/os-autoinst/basetest.pm line 346
	basetest::runtest(clone=HASH(0x561fdaf0e700)) called at /usr/lib/os-autoinst/autotest.pm line 416
	eval {...} called at /usr/lib/os-autoinst/autotest.pm line 416
	autotest::runalltests() called at /usr/lib/os-autoinst/autotest.pm line 273
	eval {...} called at /usr/lib/os-autoinst/autotest.pm line 273
	autotest::run_all() called at /usr/lib/os-autoinst/autotest.pm line 324
	autotest::__ANON__(Mojo::IOLoop::ReadWriteProcess=HASH(0x561fdb997278)) called at /usr/lib/perl5/vendor_perl/5.26.1/Mojo/IOLoop/ReadWriteProcess.pm line 329
	eval {...} called at /usr/lib/perl5/vendor_perl/5.26.1/Mojo/IOLoop/ReadWriteProcess.pm line 329
	Mojo::IOLoop::ReadWriteProcess::_fork(Mojo::IOLoop::ReadWriteProcess=HASH(0x561fdb997278), CODE(0x561fdaf26e38)) called at /usr/lib/perl5/vendor_perl/5.26.1/Mojo/IOLoop/ReadWriteProcess.pm line 492
	Mojo::IOLoop::ReadWriteProcess::start(Mojo::IOLoop::ReadWriteProcess=HASH(0x561fdb997278)) called at /usr/lib/os-autoinst/autotest.pm line 326
	autotest::start_process() called at /usr/lib/os-autoinst/OpenQA/Isotovideo/Runner.pm line 103
	OpenQA::Isotovideo::Runner::start_autotest(OpenQA::Isotovideo::Runner=HASH(0x561fd3899cd8)) called at /usr/bin/isotovideo line 172
	eval {...} called at /usr/bin/isotovideo line 161
[2024-05-28T08:30:33.016657Z] [debug] [pid:2759] tests/autoyast/clone.pm:21 called utils::zypper_call -> lib/utils.pm:597 called testapi::script_run
[2024-05-28T08:30:33.016822Z] [debug] [pid:2759] <<< testapi::script_run(cmd="zypper -n in autoyast2 ; ( exit \${PIPESTATUS[0]} )", die_on_timeout=1, output="", quiet=undef, timeout=700)
[2024-05-28T08:30:33.016943Z] [debug] [pid:2759] tests/autoyast/clone.pm:21 called utils::zypper_call -> lib/utils.pm:597 called testapi::script_run
[2024-05-28T08:30:33.017077Z] [debug] [pid:2759] <<< testapi::type_string(string="zypper -n in autoyast2 ; ( exit \${PIPESTATUS[0]} )", max_interval=250, wait_screen_change=0, wait_still_screen=0, timeout=30, similarity_level=47)
[2024-05-28T08:30:34.955426Z] [debug] [pid:2759] tests/autoyast/clone.pm:21 called utils::zypper_call -> lib/utils.pm:597 called testapi::script_run
[2024-05-28T08:30:34.955645Z] [debug] [pid:2759] <<< testapi::type_string(string="; echo N5Pyk-\$?- > /dev/ttyS0\n", max_interval=250, wait_screen_change=0, wait_still_screen=0, timeout=30, similarity_level=47)
[2024-05-28T08:30:36.069144Z] [debug] [pid:2759] tests/autoyast/clone.pm:21 called utils::zypper_call -> lib/utils.pm:597 called testapi::script_run
[2024-05-28T08:30:36.069337Z] [debug] [pid:2759] <<< testapi::wait_serial(record_output=undef, expect_not_found=0, buffer_size=undef, timeout=700, quiet=undef, regexp=qr/N5Pyk-\d+-/u, no_regex=0)
[32m[2024-05-28T08:30:38.116162Z] [debug] [pid:2759] >>> testapi::wait_serial: (?^u:N5Pyk-\d+-): ok[0m
[2024-05-28T08:30:38.116448Z] [debug] [pid:2759] tests/autoyast/clone.pm:22 called y2_module_consoletest::yast2_console_exec -> lib/y2_module_consoletest.pm:37 called testapi::script_run
[2024-05-28T08:30:38.116593Z] [debug] [pid:2759] <<< testapi::script_run(cmd="Y2DEBUG=1 ZYPP_MEDIA_CURL_DEBUG=1 Y2STRICTTEXTDOMAIN=1  yast2 --ncurses clone_system; echo yast2-clone_system-status-\$? > /dev/ttyS0", timeout=0, quiet=undef, output="", die_on_timeout=1)
[2024-05-28T08:30:38.116730Z] [debug] [pid:2759] tests/autoyast/clone.pm:22 called y2_module_consoletest::yast2_console_exec -> lib/y2_module_consoletest.pm:37 called testapi::script_run
[2024-05-28T08:30:38.116903Z] [debug] [pid:2759] <<< testapi::type_string(string="Y2DEBUG=1 ZYPP_MEDIA_CURL_DEBUG=1 Y2STRICTTEXTDOMAIN=1  yast2 --ncurses clone_system; echo yast2-clone_system-status-\$? > /dev/ttyS0", max_interval=250, wait_screen_change=0, wait_still_screen=0, timeout=30, similarity_level=47)
[2024-05-28T08:30:43.414241Z] [debug] [pid:2759] tests/autoyast/clone.pm:22 called y2_module_consoletest::yast2_console_exec -> lib/y2_module_consoletest.pm:37 called testapi::script_run
[2024-05-28T08:30:43.414429Z] [debug] [pid:2759] <<< testapi::send_key(key="ret", wait_screen_change=0)
[2024-05-28T08:30:43.683049Z] [debug] [pid:2759] tests/autoyast/clone.pm:23 called testapi::check_screen
[2024-05-28T08:30:43.683246Z] [debug] [pid:2759] <<< testapi::check_screen(mustmatch="autoyast2-install-accept", timeout=10)
[33m[2024-05-28T08:30:43.683789Z] [info] [pid:3081] ::: backend::baseclass::set_tags_to_assert: NO matching needles for autoyast2-install-accept[0m
[37m[2024-05-28T08:30:43.684157Z] [debug] [pid:3081] no match: 9.9s[0m
[37m[2024-05-28T08:30:44.685525Z] [debug] [pid:3081] no match: 8.9s[0m
[37m[2024-05-28T08:30:45.686594Z] [debug] [pid:3081] no match: 7.9s[0m
[37m[2024-05-28T08:30:46.687604Z] [debug] [pid:3081] no change: 6.9s[0m
[37m[2024-05-28T08:30:46.687747Z] [debug] [pid:3081] no match: 6.9s[0m
[37m[2024-05-28T08:30:47.688721Z] [debug] [pid:3081] no match: 5.9s[0m
[37m[2024-05-28T08:30:48.689817Z] [debug] [pid:3081] no change: 4.9s[0m
[37m[2024-05-28T08:30:48.690019Z] [debug] [pid:3081] no match: 4.9s[0m
[37m[2024-05-28T08:30:49.690823Z] [debug] [pid:3081] no change: 3.9s[0m
[37m[2024-05-28T08:30:49.690983Z] [debug] [pid:3081] no match: 3.9s[0m
[37m[2024-05-28T08:30:50.691934Z] [debug] [pid:3081] no change: 2.9s[0m
[37m[2024-05-28T08:30:50.692103Z] [debug] [pid:3081] no match: 2.9s[0m
[37m[2024-05-28T08:30:51.692578Z] [debug] [pid:3081] no change: 1.9s[0m
[37m[2024-05-28T08:30:51.692751Z] [debug] [pid:3081] no match: 1.9s[0m
[37m[2024-05-28T08:30:52.693776Z] [debug] [pid:3081] no match: 0.9s[0m
[37m[2024-05-28T08:30:53.694742Z] [debug] [pid:3081] no match: -0.1s[0m
[32m[2024-05-28T08:30:53.776598Z] [debug] [pid:2759] >>> testapi::_check_backend_response: match=autoyast2-install-accept timed out after 10 (check_screen)[0m
[2024-05-28T08:30:53.788557Z] [debug] [pid:2759] tests/autoyast/clone.pm:28 called testapi::wait_serial
[2024-05-28T08:30:53.788720Z] [debug] [pid:2759] <<< testapi::wait_serial(record_output=undef, expect_not_found=0, buffer_size=undef, timeout=1400, regexp="yast2-clone_system-status-0", quiet=undef, no_regex=0)
[32m[2024-05-28T08:31:15.843357Z] [debug] [pid:2759] >>> testapi::wait_serial: yast2-clone_system-status-0: ok[0m
[2024-05-28T08:31:15.843529Z] [debug] [pid:2759] tests/autoyast/clone.pm:29 called testapi::upload_logs
[2024-05-28T08:31:15.843647Z] [debug] [pid:2759] <<< testapi::upload_logs(file="/root/autoinst.xml", failok=0, timeout=90)
[2024-05-28T08:31:15.843787Z] [debug] [pid:2759] tests/autoyast/clone.pm:29 called testapi::upload_logs
[2024-05-28T08:31:15.843878Z] [debug] [pid:2759] <<< testapi::assert_script_run(cmd="curl --form upload=\@/root/autoinst.xml --form upname=clone-autoinst.xml http://10.0.2.2:20303/BNGyhHHiGaVcXGrV/uploadlog/autoinst.xml", timeout=90, fail_message="", quiet=undef)
[2024-05-28T08:31:15.843974Z] [debug] [pid:2759] tests/autoyast/clone.pm:29 called testapi::upload_logs
[2024-05-28T08:31:15.844101Z] [debug] [pid:2759] <<< testapi::type_string(string="curl --form upload=\@/root/autoinst.xml --form upname=clone-autoinst.xml http://10.0.2.2:20303/BNGyhHHiGaVcXGrV/uploadlog/autoinst.xml", max_interval=250, wait_screen_change=0, wait_still_screen=0, timeout=30, similarity_level=47)
[2024-05-28T08:31:20.544474Z] [debug] [pid:2759] tests/autoyast/clone.pm:29 called testapi::upload_logs
[2024-05-28T08:31:20.544783Z] [debug] [pid:2759] <<< testapi::type_string(string="; echo kCRFW-\$?- > /dev/ttyS0\n", max_interval=250, wait_screen_change=0, wait_still_screen=0, timeout=30, similarity_level=47)
[2024-05-28T08:31:21.694740Z] [debug] [pid:2759] tests/autoyast/clone.pm:29 called testapi::upload_logs
[2024-05-28T08:31:21.694957Z] [debug] [pid:2759] <<< testapi::wait_serial(timeout=90, buffer_size=undef, record_output=undef, expect_not_found=0, quiet=undef, regexp=qr/kCRFW-\d+-/u, no_regex=0)
[32m[2024-05-28T08:31:23.742777Z] [debug] [pid:2759] >>> testapi::wait_serial: (?^u:kCRFW-\d+-): ok[0m
[2024-05-28T08:31:23.742929Z] [debug] [pid:2759] tests/autoyast/clone.pm:32 called testapi::upload_logs
[2024-05-28T08:31:23.743036Z] [debug] [pid:2759] <<< testapi::upload_logs(file="/var/adm/autoinstall/cache/installedSystem.xml", failok=0, timeout=90)
[2024-05-28T08:31:23.743165Z] [debug] [pid:2759] tests/autoyast/clone.pm:32 called testapi::upload_logs
[2024-05-28T08:31:23.743255Z] [debug] [pid:2759] <<< testapi::assert_script_run(cmd="curl --form upload=\@/var/adm/autoinstall/cache/installedSystem.xml --form upname=clone-installedSystem.xml http://10.0.2.2:20303/BNGyhHHiGaVcXGrV/uploadlog/installedSystem.xml", fail_message="", timeout=90, quiet=undef)
[2024-05-28T08:31:23.743351Z] [debug] [pid:2759] tests/autoyast/clone.pm:32 called testapi::upload_logs
[2024-05-28T08:31:23.743455Z] [debug] [pid:2759] <<< testapi::type_string(string="curl --form upload=\@/var/adm/autoinstall/cache/installedSystem.xml --form upname=clone-installedSystem.xml http://10.0.2.2:20303/BNGyhHHiGaVcXGrV/uploadlog/installedSystem.xml", max_interval=250, wait_screen_change=0, wait_still_screen=0, timeout=30, similarity_level=47)
[2024-05-28T08:31:29.917297Z] [debug] [pid:2759] tests/autoyast/clone.pm:32 called testapi::upload_logs
[2024-05-28T08:31:29.917503Z] [debug] [pid:2759] <<< testapi::type_string(string="; echo 4kISt-\$?- > /dev/ttyS0\n", max_interval=250, wait_screen_change=0, wait_still_screen=0, timeout=30, similarity_level=47)
[2024-05-28T08:31:31.029811Z] [debug] [pid:2759] tests/autoyast/clone.pm:32 called testapi::upload_logs
[2024-05-28T08:31:31.030020Z] [debug] [pid:2759] <<< testapi::wait_serial(timeout=90, buffer_size=undef, expect_not_found=0, record_output=undef, no_regex=0, quiet=undef, regexp=qr/4kISt-\d+-/u)
[32m[2024-05-28T08:31:33.072585Z] [debug] [pid:2759] >>> testapi::wait_serial: (?^u:4kISt-\d+-): ok[0m
[2024-05-28T08:31:33.072746Z] [debug] [pid:2759] tests/autoyast/clone.pm:33 called testapi::assert_script_run
[2024-05-28T08:31:33.072861Z] [debug] [pid:2759] <<< testapi::assert_script_run(cmd="save_y2logs /tmp/y2logs_clone.tar.bz2", fail_message="", timeout=90, quiet=undef)
[2024-05-28T08:31:33.072950Z] [debug] [pid:2759] tests/autoyast/clone.pm:33 called testapi::assert_script_run
[2024-05-28T08:31:33.073050Z] [debug] [pid:2759] <<< testapi::type_string(string="save_y2logs /tmp/y2logs_clone.tar.bz2", max_interval=250, wait_screen_change=0, wait_still_screen=0, timeout=30, similarity_level=47)
[2024-05-28T08:31:34.353379Z] [debug] [pid:2759] tests/autoyast/clone.pm:33 called testapi::assert_script_run
[2024-05-28T08:31:34.353594Z] [debug] [pid:2759] <<< testapi::type_string(string="; echo Aw2ws-\$?- > /dev/ttyS0\n", max_interval=250, wait_screen_change=0, wait_still_screen=0, timeout=30, similarity_level=47)
[2024-05-28T08:31:35.449419Z] [debug] [pid:2759] tests/autoyast/clone.pm:33 called testapi::assert_script_run
[2024-05-28T08:31:35.449650Z] [debug] [pid:2759] <<< testapi::wait_serial(expect_not_found=0, record_output=undef, timeout=90, buffer_size=undef, regexp=qr/Aw2ws-\d+-/u, no_regex=0, quiet=undef)
[32m[2024-05-28T08:31:39.495894Z] [debug] [pid:2759] >>> testapi::wait_serial: (?^u:Aw2ws-\d+-): ok[0m
[2024-05-28T08:31:39.496049Z] [debug] [pid:2759] tests/autoyast/clone.pm:34 called testapi::upload_logs
[2024-05-28T08:31:39.496166Z] [debug] [pid:2759] <<< testapi::upload_logs(file="/tmp/y2logs_clone.tar.bz2", failok=0, timeout=90)
[2024-05-28T08:31:39.496292Z] [debug] [pid:2759] tests/autoyast/clone.pm:34 called testapi::upload_logs
[2024-05-28T08:31:39.496385Z] [debug] [pid:2759] <<< testapi::assert_script_run(cmd="curl --form upload=\@/tmp/y2logs_clone.tar.bz2 --form upname=clone-y2logs_clone.tar.bz2 http://10.0.2.2:20303/BNGyhHHiGaVcXGrV/uploadlog/y2logs_clone.tar.bz2", timeout=90, fail_message="", quiet=undef)
[2024-05-28T08:31:39.496487Z] [debug] [pid:2759] tests/autoyast/clone.pm:34 called testapi::upload_logs
[2024-05-28T08:31:39.496591Z] [debug] [pid:2759] <<< testapi::type_string(string="curl --form upload=\@/tmp/y2logs_clone.tar.bz2 --form upname=clone-y2logs_clone.tar.bz2 http://10.0.2.2:20303/BNGyhHHiGaVcXGrV/uploadlog/y2logs_clone.tar.bz2", max_interval=250, wait_screen_change=0, wait_still_screen=0, timeout=30, similarity_level=47)
[2024-05-28T08:31:45.017822Z] [debug] [pid:2759] tests/autoyast/clone.pm:34 called testapi::upload_logs
[2024-05-28T08:31:45.018038Z] [debug] [pid:2759] <<< testapi::type_string(string="; echo ZSWyl-\$?- > /dev/ttyS0\n", max_interval=250, wait_screen_change=0, wait_still_screen=0, timeout=30, similarity_level=47)
[2024-05-28T08:31:46.146057Z] [debug] [pid:2759] tests/autoyast/clone.pm:34 called testapi::upload_logs
[2024-05-28T08:31:46.146287Z] [debug] [pid:2759] <<< testapi::wait_serial(quiet=undef, regexp=qr/ZSWyl-\d+-/u, no_regex=0, timeout=90, buffer_size=undef, expect_not_found=0, record_output=undef)
[32m[2024-05-28T08:31:49.194658Z] [debug] [pid:2759] >>> testapi::wait_serial: (?^u:ZSWyl-\d+-): ok[0m
[2024-05-28T08:31:49.238162Z] [debug] [pid:2759] lib/y2_module_consoletest.pm:57 called opensusebasetest::clear_and_verify_console -> lib/opensusebasetest.pm:53 called utils::clear_console -> lib/utils.pm:387 called testapi::enter_cmd
[2024-05-28T08:31:49.238350Z] [debug] [pid:2759] <<< testapi::type_string(string="clear\n", max_interval=250, wait_screen_change=0, wait_still_screen=0, timeout=30, similarity_level=47)
[2024-05-28T08:31:49.441345Z] [debug] [pid:2759] lib/y2_module_consoletest.pm:57 called opensusebasetest::clear_and_verify_console -> lib/opensusebasetest.pm:54 called testapi::assert_screen
[2024-05-28T08:31:49.441497Z] [debug] [pid:2759] <<< testapi::assert_screen(mustmatch="cleared-console", timeout=30)
[37m[2024-05-28T08:31:49.505443Z] [debug] [pid:3081] no match: 29.9s, best candidate: cleared-console-20141130 (0.00)[0m
[32m[2024-05-28T08:31:50.538756Z] [debug] [pid:2759] >>> testapi::_handle_found_needle: found cleared-console-standard_prompt-20191207, similarity 1.00 @ 66/1[0m
[1;34m[2024-05-28T08:31:50.539269Z] [debug] [pid:2759] ||| finished clone autoyast (runtime: 80 s)[0m
[1;34m[2024-05-28T08:31:50.540158Z] [debug] [pid:2759] ||| starting validate_multi_btrfs_partitioning tests/console/validate_multi_btrfs_partitioning.pm[0m
[2024-05-28T08:31:50.540683Z] [debug] [pid:2759] tests/console/validate_multi_btrfs_partitioning.pm:26 called testapi::select_console
[2024-05-28T08:31:50.540772Z] [debug] [pid:2759] <<< testapi::select_console(testapi_console="root-console")
[2024-05-28T08:31:50.947123Z] [debug] [pid:2759] tests/console/validate_multi_btrfs_partitioning.pm:26 called testapi::select_console -> lib/susedistribution.pm:997 called testapi::assert_screen
[2024-05-28T08:31:50.947389Z] [debug] [pid:2759] <<< testapi::assert_screen(mustmatch="root-console", no_wait=1, timeout=30)
[32m[2024-05-28T08:31:51.012181Z] [debug] [pid:2759] >>> testapi::_handle_found_needle: found root-console-20200501, similarity 0.99 @ 79/1[0m
[2024-05-28T08:31:51.012575Z] [debug] [pid:2759] tests/console/validate_multi_btrfs_partitioning.pm:30 called testapi::script_output
[2024-05-28T08:31:51.012770Z] [debug] [pid:2759] <<< testapi::type_string(string="cat - > /tmp/scriptq728I.sh;", max_interval=250, wait_screen_change=0, wait_still_screen=0, timeout=30, similarity_level=47)
[2024-05-28T08:31:51.991194Z] [debug] [pid:2759] tests/console/validate_multi_btrfs_partitioning.pm:30 called testapi::script_output
[2024-05-28T08:31:51.991401Z] [debug] [pid:2759] <<< testapi::type_string(string="\n", max_interval=250, wait_screen_change=0, wait_still_screen=0, timeout=30, similarity_level=47)
[2024-05-28T08:31:52.025636Z] [debug] [pid:2759] tests/console/validate_multi_btrfs_partitioning.pm:30 called testapi::script_output
[2024-05-28T08:31:52.025828Z] [debug] [pid:2759] <<< testapi::type_string(string="btrfs filesystem show /\n", max_interval=250, wait_screen_change=0, wait_still_screen=0, timeout=30, similarity_level=47)
[2024-05-28T08:31:52.835926Z] [debug] [pid:2759] tests/console/validate_multi_btrfs_partitioning.pm:30 called testapi::script_output
[2024-05-28T08:31:52.836123Z] [debug] [pid:2759] <<< testapi::send_key(key="ctrl-d", wait_screen_change=0)
[2024-05-28T08:31:53.170916Z] [debug] [pid:2759] tests/console/validate_multi_btrfs_partitioning.pm:30 called testapi::script_output
[2024-05-28T08:31:53.171147Z] [debug] [pid:2759] <<< testapi::type_string(string="(echo q728I; bash -eox pipefail /tmp/scriptq728I.sh ; echo SCRIPT_FINISHEDq728I-\$?-) | tee /dev/ttyS0\n", max_interval=250, wait_screen_change=0, wait_still_screen=0, timeout=30, similarity_level=47)
[2024-05-28T08:31:57.018990Z] [debug] [pid:2759] tests/console/validate_multi_btrfs_partitioning.pm:30 called testapi::script_output
[2024-05-28T08:31:57.019330Z] [debug] [pid:2759] <<< testapi::wait_serial(record_output=1, expect_not_found=0, buffer_size=undef, timeout=90, quiet=undef, regexp="SCRIPT_FINISHEDq728I-\\d+-", no_regex=0)
[32m[2024-05-28T08:31:58.071662Z] [debug] [pid:2759] >>> testapi::wait_serial: SCRIPT_FINISHEDq728I-\d+-: ok[0m
[2024-05-28T08:31:58.071845Z] [debug] [pid:2759] tests/console/validate_multi_btrfs_partitioning.pm:32 called testapi::record_info
[2024-05-28T08:31:58.071961Z] [debug] [pid:2759] <<< testapi::record_info(title="Label", output="Verify label for \"/\" mount point", result="ok")
[2024-05-28T08:31:58.072164Z] [debug] [pid:2759] tests/console/validate_multi_btrfs_partitioning.pm:36 called testapi::record_info
[2024-05-28T08:31:58.072254Z] [debug] [pid:2759] <<< testapi::record_info(title="Number of devices", output="Verify the number of devices used for multi-device Btrfs with \"/\" mount point corresponds to the expected", result="ok")
[2024-05-28T08:31:58.072440Z] [debug] [pid:2759] tests/console/validate_multi_btrfs_partitioning.pm:42 called testapi::record_info
[2024-05-28T08:31:58.072521Z] [debug] [pid:2759] <<< testapi::record_info(title="/dev/vda2", output="Verify the device \"/dev/vda2\" is used in multi-device Btrfs with \"/\" mount point", result="ok")
[2024-05-28T08:31:58.072670Z] [debug] [pid:2759] tests/console/validate_multi_btrfs_partitioning.pm:42 called testapi::record_info
[2024-05-28T08:31:58.072752Z] [debug] [pid:2759] <<< testapi::record_info(title="/dev/vdb1", output="Verify the device \"/dev/vdb1\" is used in multi-device Btrfs with \"/\" mount point", result="ok")
[2024-05-28T08:31:58.073011Z] [debug] [pid:2759] tests/console/validate_multi_btrfs_partitioning.pm:30 called testapi::script_output
[2024-05-28T08:31:58.073145Z] [debug] [pid:2759] <<< testapi::type_string(string="cat - > /tmp/scriptrmF14.sh;", max_interval=250, wait_screen_change=0, wait_still_screen=0, timeout=30, similarity_level=47)
[2024-05-28T08:31:59.052143Z] [debug] [pid:2759] tests/console/validate_multi_btrfs_partitioning.pm:30 called testapi::script_output
[2024-05-28T08:31:59.052377Z] [debug] [pid:2759] <<< testapi::type_string(string="\n", max_interval=250, wait_screen_change=0, wait_still_screen=0, timeout=30, similarity_level=47)
[2024-05-28T08:31:59.087004Z] [debug] [pid:2759] tests/console/validate_multi_btrfs_partitioning.pm:30 called testapi::script_output
[2024-05-28T08:31:59.087186Z] [debug] [pid:2759] <<< testapi::type_string(string="btrfs filesystem show /test\n", max_interval=250, wait_screen_change=0, wait_still_screen=0, timeout=30, similarity_level=47)
[2024-05-28T08:32:00.030721Z] [debug] [pid:2759] tests/console/validate_multi_btrfs_partitioning.pm:30 called testapi::script_output
[2024-05-28T08:32:00.030885Z] [debug] [pid:2759] <<< testapi::send_key(key="ctrl-d", wait_screen_change=0)
[2024-05-28T08:32:00.365848Z] [debug] [pid:2759] tests/console/validate_multi_btrfs_partitioning.pm:30 called testapi::script_output
[2024-05-28T08:32:00.366157Z] [debug] [pid:2759] <<< testapi::type_string(string="(echo rmF14; bash -eox pipefail /tmp/scriptrmF14.sh ; echo SCRIPT_FINISHEDrmF14-\$?-) | tee /dev/ttyS0\n", max_interval=250, wait_screen_change=0, wait_still_screen=0, timeout=30, similarity_level=47)
[2024-05-28T08:32:04.214383Z] [debug] [pid:2759] tests/console/validate_multi_btrfs_partitioning.pm:30 called testapi::script_output
[2024-05-28T08:32:04.214612Z] [debug] [pid:2759] <<< testapi::wait_serial(regexp="SCRIPT_FINISHEDrmF14-\\d+-", quiet=undef, no_regex=0, buffer_size=undef, timeout=90, record_output=1, expect_not_found=0)
[32m[2024-05-28T08:32:05.260740Z] [debug] [pid:2759] >>> testapi::wait_serial: SCRIPT_FINISHEDrmF14-\d+-: ok[0m
[2024-05-28T08:32:05.260914Z] [debug] [pid:2759] tests/console/validate_multi_btrfs_partitioning.pm:32 called testapi::record_info
[2024-05-28T08:32:05.261026Z] [debug] [pid:2759] <<< testapi::record_info(title="Label", output="Verify label for \"/test\" mount point", result="ok")
[2024-05-28T08:32:05.261191Z] [debug] [pid:2759] tests/console/validate_multi_btrfs_partitioning.pm:36 called testapi::record_info
[2024-05-28T08:32:05.261275Z] [debug] [pid:2759] <<< testapi::record_info(title="Number of devices", output="Verify the number of devices used for multi-device Btrfs with \"/test\" mount point corresponds to the expected", result="ok")
[2024-05-28T08:32:05.261436Z] [debug] [pid:2759] tests/console/validate_multi_btrfs_partitioning.pm:42 called testapi::record_info
[2024-05-28T08:32:05.261517Z] [debug] [pid:2759] <<< testapi::record_info(title="/dev/vdc", output="Verify the device \"/dev/vdc\" is used in multi-device Btrfs with \"/test\" mount point", result="ok")
[2024-05-28T08:32:05.261669Z] [debug] [pid:2759] tests/console/validate_multi_btrfs_partitioning.pm:42 called testapi::record_info
[2024-05-28T08:32:05.261753Z] [debug] [pid:2759] <<< testapi::record_info(title="/dev/mapper/cr_test", output="Verify the device \"/dev/mapper/cr_test\" is used in multi-device Btrfs with \"/test\" mount point", result="ok")
[1;34m[2024-05-28T08:32:05.262353Z] [debug] [pid:2759] ||| finished validate_multi_btrfs_partitioning console (runtime: 15 s)[0m
[1;34m[2024-05-28T08:32:05.263216Z] [debug] [pid:2759] ||| starting validate_encrypt tests/console/validate_encrypt.pm[0m
[2024-05-28T08:32:05.263737Z] [debug] [pid:2759] tests/console/validate_encrypt.pm:25 called testapi::select_console
[2024-05-28T08:32:05.263798Z] [debug] [pid:2759] <<< testapi::select_console(testapi_console="root-console")
[2024-05-28T08:32:05.667641Z] [debug] [pid:2759] tests/console/validate_encrypt.pm:25 called testapi::select_console -> lib/susedistribution.pm:997 called testapi::assert_screen
[2024-05-28T08:32:05.667844Z] [debug] [pid:2759] <<< testapi::assert_screen(mustmatch="root-console", no_wait=1, timeout=30)
[32m[2024-05-28T08:32:05.726761Z] [debug] [pid:2759] >>> testapi::_handle_found_needle: found root-console-20200501, similarity 1.00 @ 79/33[0m
[2024-05-28T08:32:05.727048Z] [debug] [pid:2759] tests/console/validate_encrypt.pm:27 called validate_encrypt_utils::verify_crypttab_file_existence -> lib/validate_encrypt_utils.pm:93 called testapi::record_info
[2024-05-28T08:32:05.727209Z] [debug] [pid:2759] <<< testapi::record_info(title="crypttab file", output="Verify the existence of /etc/crypttab file", result="ok")
[2024-05-28T08:32:05.727484Z] [debug] [pid:2759] tests/console/validate_encrypt.pm:27 called validate_encrypt_utils::verify_crypttab_file_existence -> lib/validate_encrypt_utils.pm:94 called testapi::assert_script_run
[2024-05-28T08:32:05.727614Z] [debug] [pid:2759] <<< testapi::assert_script_run(cmd="test -f /etc/crypttab", quiet=undef, fail_message="No /etc/crypttab found", timeout=90)
[2024-05-28T08:32:05.727759Z] [debug] [pid:2759] tests/console/validate_encrypt.pm:27 called validate_encrypt_utils::verify_crypttab_file_existence -> lib/validate_encrypt_utils.pm:94 called testapi::assert_script_run
[2024-05-28T08:32:05.727874Z] [debug] [pid:2759] <<< testapi::type_string(string="test -f /etc/crypttab", max_interval=250, wait_screen_change=0, wait_still_screen=0, timeout=30, similarity_level=47)
[2024-05-28T08:32:06.436783Z] [debug] [pid:2759] tests/console/validate_encrypt.pm:27 called validate_encrypt_utils::verify_crypttab_file_existence -> lib/validate_encrypt_utils.pm:94 called testapi::assert_script_run
[2024-05-28T08:32:06.437017Z] [debug] [pid:2759] <<< testapi::type_string(string="; echo GVYpS-\$?- > /dev/ttyS0\n", max_interval=250, wait_screen_change=0, wait_still_screen=0, timeout=30, similarity_level=47)
[2024-05-28T08:32:07.583432Z] [debug] [pid:2759] tests/console/validate_encrypt.pm:27 called validate_encrypt_utils::verify_crypttab_file_existence -> lib/validate_encrypt_utils.pm:94 called testapi::assert_script_run
[2024-05-28T08:32:07.583645Z] [debug] [pid:2759] <<< testapi::wait_serial(no_regex=0, quiet=undef, regexp=qr/GVYpS-\d+-/u, buffer_size=undef, timeout=90, record_output=undef, expect_not_found=0)
[32m[2024-05-28T08:32:08.631697Z] [debug] [pid:2759] >>> testapi::wait_serial: (?^u:GVYpS-\d+-): ok[0m
[2024-05-28T08:32:08.631913Z] [debug] [pid:2759] tests/console/validate_encrypt.pm:28 called validate_encrypt_utils::parse_devices_in_crypttab -> lib/validate_encrypt_utils.pm:40 called testapi::script_output
[2024-05-28T08:32:08.632063Z] [debug] [pid:2759] <<< testapi::type_string(string="cat - > /tmp/scriptKJ0jz.sh;", max_interval=250, wait_screen_change=0, wait_still_screen=0, timeout=30, similarity_level=47)
[2024-05-28T08:32:09.626739Z] [debug] [pid:2759] tests/console/validate_encrypt.pm:28 called validate_encrypt_utils::parse_devices_in_crypttab -> lib/validate_encrypt_utils.pm:40 called testapi::script_output
[2024-05-28T08:32:09.626942Z] [debug] [pid:2759] <<< testapi::type_string(string="\n", max_interval=250, wait_screen_change=0, wait_still_screen=0, timeout=30, similarity_level=47)
[2024-05-28T08:32:09.661316Z] [debug] [pid:2759] tests/console/validate_encrypt.pm:28 called validate_encrypt_utils::parse_devices_in_crypttab -> lib/validate_encrypt_utils.pm:40 called testapi::script_output
[2024-05-28T08:32:09.661474Z] [debug] [pid:2759] <<< testapi::type_string(string="cat /etc/crypttab\n", max_interval=250, wait_screen_change=0, wait_still_screen=0, timeout=30, similarity_level=47)
[2024-05-28T08:32:10.267936Z] [debug] [pid:2759] tests/console/validate_encrypt.pm:28 called validate_encrypt_utils::parse_devices_in_crypttab -> lib/validate_encrypt_utils.pm:40 called testapi::script_output
[2024-05-28T08:32:10.268114Z] [debug] [pid:2759] <<< testapi::send_key(key="ctrl-d", wait_screen_change=0)
[2024-05-28T08:32:10.603374Z] [debug] [pid:2759] tests/console/validate_encrypt.pm:28 called validate_encrypt_utils::parse_devices_in_crypttab -> lib/validate_encrypt_utils.pm:40 called testapi::script_output
[2024-05-28T08:32:10.603589Z] [debug] [pid:2759] <<< testapi::type_string(string="(echo KJ0jz; bash -eox pipefail /tmp/scriptKJ0jz.sh ; echo SCRIPT_FINISHEDKJ0jz-\$?-) | tee /dev/ttyS0\n", max_interval=250, wait_screen_change=0, wait_still_screen=0, timeout=30, similarity_level=47)
[2024-05-28T08:32:14.496193Z] [debug] [pid:2759] tests/console/validate_encrypt.pm:28 called validate_encrypt_utils::parse_devices_in_crypttab -> lib/validate_encrypt_utils.pm:40 called testapi::script_output
[2024-05-28T08:32:14.496414Z] [debug] [pid:2759] <<< testapi::wait_serial(quiet=undef, regexp="SCRIPT_FINISHEDKJ0jz-\\d+-", no_regex=0, expect_not_found=0, record_output=1, timeout=90, buffer_size=undef)
[32m[2024-05-28T08:32:15.547210Z] [debug] [pid:2759] >>> testapi::wait_serial: SCRIPT_FINISHEDKJ0jz-\d+-: ok[0m
[2024-05-28T08:32:15.547413Z] [debug] [pid:2759] tests/console/validate_encrypt.pm:29 called validate_encrypt_utils::verify_number_of_encrypted_devices -> lib/validate_encrypt_utils.pm:115 called testapi::record_info
[2024-05-28T08:32:15.547525Z] [debug] [pid:2759] <<< testapi::record_info(title="devices number", output="Verify number of encrypted devices", result="ok")
[2024-05-28T08:32:15.547788Z] [debug] [pid:2759] tests/console/validate_encrypt.pm:31 called validate_encrypt_utils::parse_cryptsetup_status -> lib/validate_encrypt_utils.pm:70 called testapi::script_output
[2024-05-28T08:32:15.547900Z] [debug] [pid:2759] <<< testapi::type_string(string="cat - > /tmp/script~beaZ.sh;", max_interval=250, wait_screen_change=0, wait_still_screen=0, timeout=30, similarity_level=47)
[2024-05-28T08:32:16.542605Z] [debug] [pid:2759] tests/console/validate_encrypt.pm:31 called validate_encrypt_utils::parse_cryptsetup_status -> lib/validate_encrypt_utils.pm:70 called testapi::script_output
[2024-05-28T08:32:16.542834Z] [debug] [pid:2759] <<< testapi::type_string(string="\n", max_interval=250, wait_screen_change=0, wait_still_screen=0, timeout=30, similarity_level=47)
[2024-05-28T08:32:16.577194Z] [debug] [pid:2759] tests/console/validate_encrypt.pm:31 called validate_encrypt_utils::parse_cryptsetup_status -> lib/validate_encrypt_utils.pm:70 called testapi::script_output
[2024-05-28T08:32:16.577349Z] [debug] [pid:2759] <<< testapi::type_string(string="cryptsetup status cr_test\n", max_interval=250, wait_screen_change=0, wait_still_screen=0, timeout=30, similarity_level=47)
[2024-05-28T08:32:17.470046Z] [debug] [pid:2759] tests/console/validate_encrypt.pm:31 called validate_encrypt_utils::parse_cryptsetup_status -> lib/validate_encrypt_utils.pm:70 called testapi::script_output
[2024-05-28T08:32:17.470217Z] [debug] [pid:2759] <<< testapi::send_key(key="ctrl-d", wait_screen_change=0)
[2024-05-28T08:32:17.804959Z] [debug] [pid:2759] tests/console/validate_encrypt.pm:31 called validate_encrypt_utils::parse_cryptsetup_status -> lib/validate_encrypt_utils.pm:70 called testapi::script_output
[2024-05-28T08:32:17.805171Z] [debug] [pid:2759] <<< testapi::type_string(string="(echo ~beaZ; bash -eox pipefail /tmp/script~beaZ.sh ; echo SCRIPT_FINISHED~beaZ-\$?-) | tee /dev/ttyS0\n", max_interval=250, wait_screen_change=0, wait_still_screen=0, timeout=30, similarity_level=47)
[2024-05-28T08:32:21.701505Z] [debug] [pid:2759] tests/console/validate_encrypt.pm:31 called validate_encrypt_utils::parse_cryptsetup_status -> lib/validate_encrypt_utils.pm:70 called testapi::script_output
[2024-05-28T08:32:21.701704Z] [debug] [pid:2759] <<< testapi::wait_serial(quiet=undef, no_regex=0, regexp="SCRIPT_FINISHED~beaZ-\\d+-", expect_not_found=0, record_output=1, timeout=90, buffer_size=undef)
[32m[2024-05-28T08:32:22.748622Z] [debug] [pid:2759] >>> testapi::wait_serial: SCRIPT_FINISHED~beaZ-\d+-: ok[0m
[2024-05-28T08:32:22.748900Z] [debug] [pid:2759] tests/console/validate_encrypt.pm:32 called validate_encrypt_utils::verify_cryptsetup_message -> lib/validate_encrypt_utils.pm:139 called testapi::record_info
[2024-05-28T08:32:22.749029Z] [debug] [pid:2759] <<< testapi::record_info(title="Assert volumes status", output="Verify crypted volume status based on test_data expectations", result="ok")
[2024-05-28T08:32:22.749246Z] [debug] [pid:2759] tests/console/validate_encrypt.pm:33 called validate_encrypt_utils::verify_cryptsetup_properties -> lib/validate_encrypt_utils.pm:161 called testapi::record_info
[2024-05-28T08:32:22.749358Z] [debug] [pid:2759] <<< testapi::record_info(title="params", output="Verify parameters, that are set for crypted volumes", result="ok")
[37m[2024-05-28T08:32:22.749539Z] [debug] [pid:2759] Verifying that expected property aes-xts-plain64 corresponds to the actual aes-xts-plain64[0m
[37m[2024-05-28T08:32:22.749623Z] [debug] [pid:2759] Verifying that expected property /dev/vdd1 corresponds to the actual /dev/vdd1[0m
[37m[2024-05-28T08:32:22.749684Z] [debug] [pid:2759] Verifying that expected property dm-crypt corresponds to the actual dm-crypt[0m
[37m[2024-05-28T08:32:22.749738Z] [debug] [pid:2759] Verifying that expected property read/write corresponds to the actual read/write[0m
[37m[2024-05-28T08:32:22.749791Z] [debug] [pid:2759] Verifying that expected property LUKS1 corresponds to the actual LUKS1[0m
[2024-05-28T08:32:22.749897Z] [debug] [pid:2759] tests/console/validate_encrypt.pm:40 called validate_encrypt_utils::verify_restoring_luks_backups -> lib/validate_encrypt_utils.pm:196 called testapi::record_info
[2024-05-28T08:32:22.749989Z] [debug] [pid:2759] <<< testapi::record_info(title="LUKS", output="Verify storing and restoring for binary backups of LUKS header and keyslot areas.", result="ok")
[2024-05-28T08:32:22.750168Z] [debug] [pid:2759] tests/console/validate_encrypt.pm:40 called validate_encrypt_utils::verify_restoring_luks_backups -> lib/validate_encrypt_utils.pm:197 called testapi::assert_script_run
[2024-05-28T08:32:22.750273Z] [debug] [pid:2759] <<< testapi::assert_script_run(cmd="cryptsetup -v isLuks UUID=4a7ad552-7e65-422f-9db5-e8a39827cc1e", quiet=undef, timeout=90, fail_message="")
[2024-05-28T08:32:22.750384Z] [debug] [pid:2759] tests/console/validate_encrypt.pm:40 called validate_encrypt_utils::verify_restoring_luks_backups -> lib/validate_encrypt_utils.pm:197 called testapi::assert_script_run
[2024-05-28T08:32:22.750507Z] [debug] [pid:2759] <<< testapi::type_string(string="cryptsetup -v isLuks UUID=4a7ad552-7e65-422f-9db5-e8a39827cc1e", max_interval=250, wait_screen_change=0, wait_still_screen=0, timeout=30, similarity_level=47)
[2024-05-28T08:32:24.926856Z] [debug] [pid:2759] tests/console/validate_encrypt.pm:40 called validate_encrypt_utils::verify_restoring_luks_backups -> lib/validate_encrypt_utils.pm:197 called testapi::assert_script_run
[2024-05-28T08:32:24.927075Z] [debug] [pid:2759] <<< testapi::type_string(string="; echo CoCt1-\$?- > /dev/ttyS0\n", max_interval=250, wait_screen_change=0, wait_still_screen=0, timeout=30, similarity_level=47)
[2024-05-28T08:32:26.042533Z] [debug] [pid:2759] tests/console/validate_encrypt.pm:40 called validate_encrypt_utils::verify_restoring_luks_backups -> lib/validate_encrypt_utils.pm:197 called testapi::assert_script_run
[2024-05-28T08:32:26.042871Z] [debug] [pid:2759] <<< testapi::wait_serial(expect_not_found=0, record_output=undef, buffer_size=undef, timeout=90, regexp=qr/CoCt1-\d+-/u, quiet=undef, no_regex=0)
[32m[2024-05-28T08:32:28.091057Z] [debug] [pid:2759] >>> testapi::wait_serial: (?^u:CoCt1-\d+-): ok[0m
[2024-05-28T08:32:28.091230Z] [debug] [pid:2759] tests/console/validate_encrypt.pm:40 called validate_encrypt_utils::verify_restoring_luks_backups -> lib/validate_encrypt_utils.pm:198 called testapi::assert_script_run
[2024-05-28T08:32:28.091349Z] [debug] [pid:2759] <<< testapi::assert_script_run(cmd="cryptsetup -v luksUUID UUID=4a7ad552-7e65-422f-9db5-e8a39827cc1e", quiet=undef, timeout=90, fail_message="")
[2024-05-28T08:32:28.091448Z] [debug] [pid:2759] tests/console/validate_encrypt.pm:40 called validate_encrypt_utils::verify_restoring_luks_backups -> lib/validate_encrypt_utils.pm:198 called testapi::assert_script_run
[2024-05-28T08:32:28.091546Z] [debug] [pid:2759] <<< testapi::type_string(string="cryptsetup -v luksUUID UUID=4a7ad552-7e65-422f-9db5-e8a39827cc1e", max_interval=250, wait_screen_change=0, wait_still_screen=0, timeout=30, similarity_level=47)
[2024-05-28T08:32:30.388998Z] [debug] [pid:2759] tests/console/validate_encrypt.pm:40 called validate_encrypt_utils::verify_restoring_luks_backups -> lib/validate_encrypt_utils.pm:198 called testapi::assert_script_run
[2024-05-28T08:32:30.389304Z] [debug] [pid:2759] <<< testapi::type_string(string="; echo Pbj1A-\$?- > /dev/ttyS0\n", max_interval=250, wait_screen_change=0, wait_still_screen=0, timeout=30, similarity_level=47)
[2024-05-28T08:32:31.503537Z] [debug] [pid:2759] tests/console/validate_encrypt.pm:40 called validate_encrypt_utils::verify_restoring_luks_backups -> lib/validate_encrypt_utils.pm:198 called testapi::assert_script_run
[2024-05-28T08:32:31.503755Z] [debug] [pid:2759] <<< testapi::wait_serial(expect_not_found=0, record_output=undef, buffer_size=undef, timeout=90, regexp=qr/Pbj1A-\d+-/u, no_regex=0, quiet=undef)
[32m[2024-05-28T08:32:33.555681Z] [debug] [pid:2759] >>> testapi::wait_serial: (?^u:Pbj1A-\d+-): ok[0m
[2024-05-28T08:32:33.555855Z] [debug] [pid:2759] tests/console/validate_encrypt.pm:40 called validate_encrypt_utils::verify_restoring_luks_backups -> lib/validate_encrypt_utils.pm:199 called testapi::assert_script_run
[2024-05-28T08:32:33.555974Z] [debug] [pid:2759] <<< testapi::assert_script_run(cmd="cryptsetup -v luksDump UUID=4a7ad552-7e65-422f-9db5-e8a39827cc1e", quiet=undef, fail_message="", timeout=90)
[2024-05-28T08:32:33.556086Z] [debug] [pid:2759] tests/console/validate_encrypt.pm:40 called validate_encrypt_utils::verify_restoring_luks_backups -> lib/validate_encrypt_utils.pm:199 called testapi::assert_script_run
[2024-05-28T08:32:33.556191Z] [debug] [pid:2759] <<< testapi::type_string(string="cryptsetup -v luksDump UUID=4a7ad552-7e65-422f-9db5-e8a39827cc1e", max_interval=250, wait_screen_change=0, wait_still_screen=0, timeout=30, similarity_level=47)
[2024-05-28T08:32:35.798580Z] [debug] [pid:2759] tests/console/validate_encrypt.pm:40 called validate_encrypt_utils::verify_restoring_luks_backups -> lib/validate_encrypt_utils.pm:199 called testapi::assert_script_run
[2024-05-28T08:32:35.798789Z] [debug] [pid:2759] <<< testapi::type_string(string="; echo A5y9j-\$?- > /dev/ttyS0\n", max_interval=250, wait_screen_change=0, wait_still_screen=0, timeout=30, similarity_level=47)
[2024-05-28T08:32:36.896813Z] [debug] [pid:2759] tests/console/validate_encrypt.pm:40 called validate_encrypt_utils::verify_restoring_luks_backups -> lib/validate_encrypt_utils.pm:199 called testapi::assert_script_run
[2024-05-28T08:32:36.897038Z] [debug] [pid:2759] <<< testapi::wait_serial(expect_not_found=0, record_output=undef, timeout=90, buffer_size=undef, regexp=qr/A5y9j-\d+-/u, quiet=undef, no_regex=0)
[32m[2024-05-28T08:32:38.949963Z] [debug] [pid:2759] >>> testapi::wait_serial: (?^u:A5y9j-\d+-): ok[0m
[2024-05-28T08:32:38.950144Z] [debug] [pid:2759] tests/console/validate_encrypt.pm:40 called validate_encrypt_utils::verify_restoring_luks_backups -> lib/validate_encrypt_utils.pm:200 called testapi::assert_script_run
[2024-05-28T08:32:38.950269Z] [debug] [pid:2759] <<< testapi::assert_script_run(cmd="cryptsetup -v luksHeaderBackup UUID=4a7ad552-7e65-422f-9db5-e8a39827cc1e --header-backup-file /root/bkp_luks_header", timeout=90, fail_message="", quiet=undef)
[2024-05-28T08:32:38.950368Z] [debug] [pid:2759] tests/console/validate_encrypt.pm:40 called validate_encrypt_utils::verify_restoring_luks_backups -> lib/validate_encrypt_utils.pm:200 called testapi::assert_script_run
[2024-05-28T08:32:38.950475Z] [debug] [pid:2759] <<< testapi::type_string(string="cryptsetup -v luksHeaderBackup UUID=4a7ad552-7e65-422f-9db5-e8a39827cc1e --header-backup-file /root/bkp_luks_header", max_interval=250, wait_screen_change=0, wait_still_screen=0, timeout=30, similarity_level=47)
[2024-05-28T08:32:42.959800Z] [debug] [pid:2759] tests/console/validate_encrypt.pm:40 called validate_encrypt_utils::verify_restoring_luks_backups -> lib/validate_encrypt_utils.pm:200 called testapi::assert_script_run
[2024-05-28T08:32:42.960094Z] [debug] [pid:2759] <<< testapi::type_string(string="; echo RZrL3-\$?- > /dev/ttyS0\n", max_interval=250, wait_screen_change=0, wait_still_screen=0, timeout=30, similarity_level=47)
[2024-05-28T08:32:44.095221Z] [debug] [pid:2759] tests/console/validate_encrypt.pm:40 called validate_encrypt_utils::verify_restoring_luks_backups -> lib/validate_encrypt_utils.pm:200 called testapi::assert_script_run
[2024-05-28T08:32:44.095415Z] [debug] [pid:2759] <<< testapi::wait_serial(expect_not_found=0, record_output=undef, timeout=90, buffer_size=undef, quiet=undef, regexp=qr/RZrL3-\d+-/u, no_regex=0)
[32m[2024-05-28T08:32:46.141948Z] [debug] [pid:2759] >>> testapi::wait_serial: (?^u:RZrL3-\d+-): ok[0m
[2024-05-28T08:32:46.142193Z] [debug] [pid:2759] tests/console/validate_encrypt.pm:40 called validate_encrypt_utils::verify_restoring_luks_backups -> lib/validate_encrypt_utils.pm:202 called testapi::validate_script_output
[2024-05-28T08:32:46.142379Z] [debug] [pid:2759] <<< testapi::type_string(string="cat - > /tmp/scriptiSwUD.sh;", max_interval=250, wait_screen_change=0, wait_still_screen=0, timeout=30, similarity_level=47)
[2024-05-28T08:32:47.155175Z] [debug] [pid:2759] tests/console/validate_encrypt.pm:40 called validate_encrypt_utils::verify_restoring_luks_backups -> lib/validate_encrypt_utils.pm:202 called testapi::validate_script_output
[2024-05-28T08:32:47.155502Z] [debug] [pid:2759] <<< testapi::type_string(string="\n", max_interval=250, wait_screen_change=0, wait_still_screen=0, timeout=30, similarity_level=47)
[2024-05-28T08:32:47.190200Z] [debug] [pid:2759] tests/console/validate_encrypt.pm:40 called validate_encrypt_utils::verify_restoring_luks_backups -> lib/validate_encrypt_utils.pm:202 called testapi::validate_script_output
[2024-05-28T08:32:47.190352Z] [debug] [pid:2759] <<< testapi::type_string(string="file /root/bkp_luks_header\n", max_interval=250, wait_screen_change=0, wait_still_screen=0, timeout=30, similarity_level=47)
[2024-05-28T08:32:48.136728Z] [debug] [pid:2759] tests/console/validate_encrypt.pm:40 called validate_encrypt_utils::verify_restoring_luks_backups -> lib/validate_encrypt_utils.pm:202 called testapi::validate_script_output
[2024-05-28T08:32:48.136935Z] [debug] [pid:2759] <<< testapi::send_key(key="ctrl-d", wait_screen_change=0)
[2024-05-28T08:32:48.472127Z] [debug] [pid:2759] tests/console/validate_encrypt.pm:40 called validate_encrypt_utils::verify_restoring_luks_backups -> lib/validate_encrypt_utils.pm:202 called testapi::validate_script_output
[2024-05-28T08:32:48.472321Z] [debug] [pid:2759] <<< testapi::type_string(string="(echo iSwUD; bash -eox pipefail /tmp/scriptiSwUD.sh ; echo SCRIPT_FINISHEDiSwUD-\$?-) | tee /dev/ttyS0\n", max_interval=250, wait_screen_change=0, wait_still_screen=0, timeout=30, similarity_level=47)
[2024-05-28T08:32:52.420808Z] [debug] [pid:2759] tests/console/validate_encrypt.pm:40 called validate_encrypt_utils::verify_restoring_luks_backups -> lib/validate_encrypt_utils.pm:202 called testapi::validate_script_output
[2024-05-28T08:32:52.421151Z] [debug] [pid:2759] <<< testapi::wait_serial(expect_not_found=0, record_output=1, timeout=90, buffer_size=undef, quiet=1, regexp="SCRIPT_FINISHEDiSwUD-\\d+-", no_regex=0)
[32m[2024-05-28T08:32:54.424425Z] [debug] [pid:2759] >>> testapi::wait_serial: SCRIPT_FINISHEDiSwUD-\d+-: ok[0m
[2024-05-28T08:32:54.426763Z] [debug] [pid:2759] tests/console/validate_encrypt.pm:40 called validate_encrypt_utils::verify_restoring_luks_backups -> lib/validate_encrypt_utils.pm:203 called testapi::assert_script_run
[2024-05-28T08:32:54.427022Z] [debug] [pid:2759] <<< testapi::assert_script_run(cmd="cryptsetup -v --batch-mode luksHeaderRestore UUID=4a7ad552-7e65-422f-9db5-e8a39827cc1e --header-backup-file /root/bkp_luks_header", fail_message="", timeout=90, quiet=undef)
[2024-05-28T08:32:54.427215Z] [debug] [pid:2759] tests/console/validate_encrypt.pm:40 called validate_encrypt_utils::verify_restoring_luks_backups -> lib/validate_encrypt_utils.pm:203 called testapi::assert_script_run
[2024-05-28T08:32:54.427438Z] [debug] [pid:2759] <<< testapi::type_string(string="cryptsetup -v --batch-mode luksHeaderRestore UUID=4a7ad552-7e65-422f-9db5-e8a39827cc1e --header-backup-file /root/bkp_luks_header", max_interval=250, wait_screen_change=0, wait_still_screen=0, timeout=30, similarity_level=47)
[2024-05-28T08:32:58.917252Z] [debug] [pid:2759] tests/console/validate_encrypt.pm:40 called validate_encrypt_utils::verify_restoring_luks_backups -> lib/validate_encrypt_utils.pm:203 called testapi::assert_script_run
[2024-05-28T08:32:58.917466Z] [debug] [pid:2759] <<< testapi::type_string(string="; echo 5mrLV-\$?- > /dev/ttyS0\n", max_interval=250, wait_screen_change=0, wait_still_screen=0, timeout=30, similarity_level=47)
[2024-05-28T08:33:00.029522Z] [debug] [pid:2759] tests/console/validate_encrypt.pm:40 called validate_encrypt_utils::verify_restoring_luks_backups -> lib/validate_encrypt_utils.pm:203 called testapi::assert_script_run
[2024-05-28T08:33:00.029850Z] [debug] [pid:2759] <<< testapi::wait_serial(expect_not_found=0, record_output=undef, buffer_size=undef, timeout=90, no_regex=0, regexp=qr/5mrLV-\d+-/u, quiet=undef)
[32m[2024-05-28T08:33:02.076196Z] [debug] [pid:2759] >>> testapi::wait_serial: (?^u:5mrLV-\d+-): ok[0m
[2024-05-28T08:33:02.076374Z] [debug] [pid:2759] tests/console/validate_encrypt.pm:40 called validate_encrypt_utils::verify_restoring_luks_backups -> lib/validate_encrypt_utils.pm:205 called testapi::assert_script_run
[2024-05-28T08:33:02.076492Z] [debug] [pid:2759] <<< testapi::assert_script_run(cmd="rm -rf /root/bkp_luks_header", fail_message="", timeout=90, quiet=undef)
[2024-05-28T08:33:02.076592Z] [debug] [pid:2759] tests/console/validate_encrypt.pm:40 called validate_encrypt_utils::verify_restoring_luks_backups -> lib/validate_encrypt_utils.pm:205 called testapi::assert_script_run
[2024-05-28T08:33:02.076696Z] [debug] [pid:2759] <<< testapi::type_string(string="rm -rf /root/bkp_luks_header", max_interval=250, wait_screen_change=0, wait_still_screen=0, timeout=30, similarity_level=47)
[2024-05-28T08:33:03.054367Z] [debug] [pid:2759] tests/console/validate_encrypt.pm:40 called validate_encrypt_utils::verify_restoring_luks_backups -> lib/validate_encrypt_utils.pm:205 called testapi::assert_script_run
[2024-05-28T08:33:03.054575Z] [debug] [pid:2759] <<< testapi::type_string(string="; echo zGPh_-\$?- > /dev/ttyS0\n", max_interval=250, wait_screen_change=0, wait_still_screen=0, timeout=30, similarity_level=47)
[2024-05-28T08:33:04.184483Z] [debug] [pid:2759] tests/console/validate_encrypt.pm:40 called validate_encrypt_utils::verify_restoring_luks_backups -> lib/validate_encrypt_utils.pm:205 called testapi::assert_script_run
[2024-05-28T08:33:04.184704Z] [debug] [pid:2759] <<< testapi::wait_serial(no_regex=0, regexp=qr/zGPh_-\d+-/u, quiet=undef, buffer_size=undef, timeout=90, expect_not_found=0, record_output=undef)
[32m[2024-05-28T08:33:05.231688Z] [debug] [pid:2759] >>> testapi::wait_serial: (?^u:zGPh_-\d+-): ok[0m
[1;34m[2024-05-28T08:33:05.232405Z] [debug] [pid:2759] ||| finished validate_encrypt console (runtime: 60 s)[0m
[1;34m[2024-05-28T08:33:05.233316Z] [debug] [pid:2759] ||| starting verify_cloned_profile tests/autoyast/verify_cloned_profile.pm[0m
[2024-05-28T08:33:05.233938Z] [debug] [pid:2759] tests/autoyast/verify_cloned_profile.pm:18 called autoyast::validate_autoyast_profile -> lib/autoyast.pm:301 called autoyast::init_autoyast_profile -> lib/autoyast.pm:236 called testapi::select_console
[2024-05-28T08:33:05.234023Z] [debug] [pid:2759] <<< testapi::select_console(testapi_console="root-console")
[2024-05-28T08:33:05.638021Z] [debug] [pid:2759] tests/autoyast/verify_cloned_profile.pm:18 called autoyast::validate_autoyast_profile -> lib/autoyast.pm:301 called autoyast::init_autoyast_profile -> lib/autoyast.pm:236 called testapi::select_console -> lib/susedistribution.pm:997 called testapi::assert_screen
[2024-05-28T08:33:05.638208Z] [debug] [pid:2759] <<< testapi::assert_screen(mustmatch="root-console", timeout=30, no_wait=1)
[37m[2024-05-28T08:33:05.644917Z] [debug] [pid:3081] no match: 29.9s, best candidate: root-console-20200501 (0.92)[0m
[37m[2024-05-28T08:33:05.745377Z] [debug] [pid:3081] no change: 29.8s[0m
[37m[2024-05-28T08:33:05.750527Z] [debug] [pid:3081] no match: 29.8s, best candidate: root-console-20200501 (0.92)[0m
[37m[2024-05-28T08:33:05.850956Z] [debug] [pid:3081] no change: 29.7s[0m
[37m[2024-05-28T08:33:05.854980Z] [debug] [pid:3081] no match: 29.7s, best candidate: root-console-20200501 (0.92)[0m
[37m[2024-05-28T08:33:05.955391Z] [debug] [pid:3081] no change: 29.6s[0m
[37m[2024-05-28T08:33:05.960663Z] [debug] [pid:3081] no match: 29.6s, best candidate: root-console-20200501 (0.92)[0m
[37m[2024-05-28T08:33:06.061079Z] [debug] [pid:3081] no change: 29.5s[0m
[37m[2024-05-28T08:33:06.065932Z] [debug] [pid:3081] no match: 29.5s, best candidate: root-console-20200501 (0.92)[0m
[37m[2024-05-28T08:33:06.166370Z] [debug] [pid:3081] no change: 29.4s[0m
[37m[2024-05-28T08:33:06.171373Z] [debug] [pid:3081] no match: 29.4s, best candidate: root-console-20200501 (0.92)[0m
[37m[2024-05-28T08:33:06.278961Z] [debug] [pid:3081] no match: 29.3s, best candidate: root-console-20200501 (0.92)[0m
[37m[2024-05-28T08:33:06.379415Z] [debug] [pid:3081] no change: 29.2s[0m
[37m[2024-05-28T08:33:06.384744Z] [debug] [pid:3081] no match: 29.2s, best candidate: root-console-20200501 (0.92)[0m
[37m[2024-05-28T08:33:06.485192Z] [debug] [pid:3081] no change: 29.1s[0m
[37m[2024-05-28T08:33:06.490242Z] [debug] [pid:3081] no match: 29.1s, best candidate: root-console-20200501 (0.92)[0m
[37m[2024-05-28T08:33:06.590678Z] [debug] [pid:3081] no change: 29.0s[0m
[37m[2024-05-28T08:33:06.595654Z] [debug] [pid:3081] no match: 29.0s, best candidate: root-console-20200501 (0.92)[0m
[37m[2024-05-28T08:33:06.703396Z] [debug] [pid:3081] no match: 28.9s, best candidate: root-console-20200501 (0.92)[0m
[37m[2024-05-28T08:33:06.803841Z] [debug] [pid:3081] no change: 28.8s[0m
[37m[2024-05-28T08:33:06.808914Z] [debug] [pid:3081] no match: 28.8s, best candidate: root-console-20200501 (0.92)[0m
[37m[2024-05-28T08:33:06.909360Z] [debug] [pid:3081] no change: 28.7s[0m
[37m[2024-05-28T08:33:06.914348Z] [debug] [pid:3081] no match: 28.7s, best candidate: root-console-20200501 (0.92)[0m
[37m[2024-05-28T08:33:07.014825Z] [debug] [pid:3081] no change: 28.6s[0m
[37m[2024-05-28T08:33:07.020087Z] [debug] [pid:3081] no match: 28.6s, best candidate: root-console-20200501 (0.92)[0m
[37m[2024-05-28T08:33:07.120557Z] [debug] [pid:3081] no change: 28.5s[0m
[37m[2024-05-28T08:33:07.125557Z] [debug] [pid:3081] no match: 28.5s, best candidate: root-console-20200501 (0.92)[0m
[37m[2024-05-28T08:33:07.226018Z] [debug] [pid:3081] no change: 28.4s[0m
[37m[2024-05-28T08:33:07.230162Z] [debug] [pid:3081] no match: 28.4s, best candidate: root-console-20200501 (0.92)[0m
[37m[2024-05-28T08:33:07.330611Z] [debug] [pid:3081] no change: 28.3s[0m
[37m[2024-05-28T08:33:07.335627Z] [debug] [pid:3081] no match: 28.3s, best candidate: root-console-20200501 (0.92)[0m
[37m[2024-05-28T08:33:07.436092Z] [debug] [pid:3081] no change: 28.2s[0m
[37m[2024-05-28T08:33:07.441076Z] [debug] [pid:3081] no match: 28.2s, best candidate: root-console-20200501 (0.92)[0m
[37m[2024-05-28T08:33:07.541542Z] [debug] [pid:3081] no change: 28.0s[0m
[37m[2024-05-28T08:33:07.546539Z] [debug] [pid:3081] no match: 28.0s, best candidate: root-console-20200501 (0.92)[0m
[37m[2024-05-28T08:33:07.647009Z] [debug] [pid:3081] no change: 27.9s[0m
[37m[2024-05-28T08:33:07.652031Z] [debug] [pid:3081] no match: 27.9s, best candidate: root-console-20200501 (0.92)[0m
[37m[2024-05-28T08:33:07.759696Z] [debug] [pid:3081] no match: 27.8s, best candidate: root-console-20200501 (0.92)[0m
[37m[2024-05-28T08:33:07.860171Z] [debug] [pid:3081] no change: 27.7s[0m
[37m[2024-05-28T08:33:07.865166Z] [debug] [pid:3081] no match: 27.7s, best candidate: root-console-20200501 (0.92)[0m
[37m[2024-05-28T08:33:07.965635Z] [debug] [pid:3081] no change: 27.6s[0m
[37m[2024-05-28T08:33:07.970634Z] [debug] [pid:3081] no match: 27.6s, best candidate: root-console-20200501 (0.92)[0m
[37m[2024-05-28T08:33:08.071086Z] [debug] [pid:3081] no change: 27.5s[0m
[37m[2024-05-28T08:33:08.076136Z] [debug] [pid:3081] no match: 27.5s, best candidate: root-console-20200501 (0.92)[0m
[37m[2024-05-28T08:33:08.176868Z] [debug] [pid:3081] no change: 27.4s[0m
[37m[2024-05-28T08:33:08.181638Z] [debug] [pid:3081] no match: 27.4s, best candidate: root-console-20200501 (0.92)[0m
[37m[2024-05-28T08:33:08.282095Z] [debug] [pid:3081] no change: 27.3s[0m
[37m[2024-05-28T08:33:08.287102Z] [debug] [pid:3081] no match: 27.3s, best candidate: root-console-20200501 (0.92)[0m
[37m[2024-05-28T08:33:08.387570Z] [debug] [pid:3081] no change: 27.2s[0m
[37m[2024-05-28T08:33:08.392560Z] [debug] [pid:3081] no match: 27.2s, best candidate: root-console-20200501 (0.92)[0m
[37m[2024-05-28T08:33:08.493008Z] [debug] [pid:3081] no change: 27.1s[0m
[37m[2024-05-28T08:33:08.498034Z] [debug] [pid:3081] no match: 27.1s, best candidate: root-console-20200501 (0.92)[0m
[37m[2024-05-28T08:33:08.598484Z] [debug] [pid:3081] no change: 27.0s[0m
[37m[2024-05-28T08:33:08.603469Z] [debug] [pid:3081] no match: 27.0s, best candidate: root-console-20200501 (0.92)[0m
[37m[2024-05-28T08:33:08.703939Z] [debug] [pid:3081] no change: 26.9s[0m
[37m[2024-05-28T08:33:08.708950Z] [debug] [pid:3081] no match: 26.9s, best candidate: root-console-20200501 (0.92)[0m
[37m[2024-05-28T08:33:08.809417Z] [debug] [pid:3081] no change: 26.8s[0m
[37m[2024-05-28T08:33:08.814450Z] [debug] [pid:3081] no match: 26.8s, best candidate: root-console-20200501 (0.92)[0m
[37m[2024-05-28T08:33:08.914913Z] [debug] [pid:3081] no change: 26.7s[0m
[37m[2024-05-28T08:33:08.919895Z] [debug] [pid:3081] no match: 26.7s, best candidate: root-console-20200501 (0.92)[0m
[37m[2024-05-28T08:33:09.020378Z] [debug] [pid:3081] no change: 26.6s[0m
[37m[2024-05-28T08:33:09.025279Z] [debug] [pid:3081] no match: 26.6s, best candidate: root-console-20200501 (0.92)[0m
[37m[2024-05-28T08:33:09.125735Z] [debug] [pid:3081] no change: 26.5s[0m
[37m[2024-05-28T08:33:09.130728Z] [debug] [pid:3081] no match: 26.5s, best candidate: root-console-20200501 (0.92)[0m
[37m[2024-05-28T08:33:09.238762Z] [debug] [pid:3081] no match: 26.4s, best candidate: root-console-20200501 (0.92)[0m
[37m[2024-05-28T08:33:09.339258Z] [debug] [pid:3081] no change: 26.2s[0m
[37m[2024-05-28T08:33:09.344268Z] [debug] [pid:3081] no match: 26.2s, best candidate: root-console-20200501 (0.92)[0m
[37m[2024-05-28T08:33:09.444729Z] [debug] [pid:3081] no change: 26.1s[0m
[37m[2024-05-28T08:33:09.449713Z] [debug] [pid:3081] no match: 26.1s, best candidate: root-console-20200501 (0.92)[0m
[37m[2024-05-28T08:33:09.550194Z] [debug] [pid:3081] no change: 26.0s[0m
[37m[2024-05-28T08:33:09.555181Z] [debug] [pid:3081] no match: 26.0s, best candidate: root-console-20200501 (0.92)[0m
[32m[2024-05-28T08:33:09.854441Z] [debug] [pid:2759] >>> testapi::_handle_found_needle: found root-console-20180724, similarity 1.00 @ 80/752[0m
[2024-05-28T08:33:09.854632Z] [debug] [pid:2759] tests/autoyast/verify_cloned_profile.pm:18 called autoyast::validate_autoyast_profile -> lib/autoyast.pm:301 called autoyast::init_autoyast_profile -> lib/autoyast.pm:239 called testapi::script_run
[2024-05-28T08:33:09.854762Z] [debug] [pid:2759] <<< testapi::script_run(cmd="[ -e /root/autoinst.xml ]", timeout=30, quiet=undef, output="", die_on_timeout=1)
[2024-05-28T08:33:09.854874Z] [debug] [pid:2759] tests/autoyast/verify_cloned_profile.pm:18 called autoyast::validate_autoyast_profile -> lib/autoyast.pm:301 called autoyast::init_autoyast_profile -> lib/autoyast.pm:239 called testapi::script_run
[2024-05-28T08:33:09.854973Z] [debug] [pid:2759] <<< testapi::type_string(string="[ -e /root/autoinst.xml ]", max_interval=250, wait_screen_change=0, wait_still_screen=0, timeout=30, similarity_level=47)
[2024-05-28T08:33:10.698559Z] [debug] [pid:2759] tests/autoyast/verify_cloned_profile.pm:18 called autoyast::validate_autoyast_profile -> lib/autoyast.pm:301 called autoyast::init_autoyast_profile -> lib/autoyast.pm:239 called testapi::script_run
[2024-05-28T08:33:10.698752Z] [debug] [pid:2759] <<< testapi::type_string(string="; echo pX47O-\$?- > /dev/ttyS0\n", max_interval=250, wait_screen_change=0, wait_still_screen=0, timeout=30, similarity_level=47)
[2024-05-28T08:33:11.811255Z] [debug] [pid:2759] tests/autoyast/verify_cloned_profile.pm:18 called autoyast::validate_autoyast_profile -> lib/autoyast.pm:301 called autoyast::init_autoyast_profile -> lib/autoyast.pm:239 called testapi::script_run
[2024-05-28T08:33:11.811466Z] [debug] [pid:2759] <<< testapi::wait_serial(regexp=qr/pX47O-\d+-/u, no_regex=0, quiet=undef, buffer_size=undef, timeout=30, expect_not_found=0, record_output=undef)
[32m[2024-05-28T08:33:12.857913Z] [debug] [pid:2759] >>> testapi::wait_serial: (?^u:pX47O-\d+-): ok[0m
[2024-05-28T08:33:12.858124Z] [debug] [pid:2759] tests/autoyast/verify_cloned_profile.pm:18 called autoyast::validate_autoyast_profile -> lib/autoyast.pm:301 called autoyast::init_autoyast_profile -> lib/autoyast.pm:243 called testapi::script_output
[2024-05-28T08:33:12.858265Z] [debug] [pid:2759] <<< testapi::type_string(string="cat - > /tmp/scriptsx~9G.sh;", max_interval=250, wait_screen_change=0, wait_still_screen=0, timeout=30, similarity_level=47)
[2024-05-28T08:33:13.854941Z] [debug] [pid:2759] tests/autoyast/verify_cloned_profile.pm:18 called autoyast::validate_autoyast_profile -> lib/autoyast.pm:301 called autoyast::init_autoyast_profile -> lib/autoyast.pm:243 called testapi::script_output
[2024-05-28T08:33:13.855159Z] [debug] [pid:2759] <<< testapi::type_string(string="\n", max_interval=250, wait_screen_change=0, wait_still_screen=0, timeout=30, similarity_level=47)
[2024-05-28T08:33:13.889485Z] [debug] [pid:2759] tests/autoyast/verify_cloned_profile.pm:18 called autoyast::validate_autoyast_profile -> lib/autoyast.pm:301 called autoyast::init_autoyast_profile -> lib/autoyast.pm:243 called testapi::script_output
[2024-05-28T08:33:13.889757Z] [debug] [pid:2759] <<< testapi::type_string(string="cat /root/autoinst.xml\n", max_interval=250, wait_screen_change=0, wait_still_screen=0, timeout=30, similarity_level=47)
[2024-05-28T08:33:14.668971Z] [debug] [pid:2759] tests/autoyast/verify_cloned_profile.pm:18 called autoyast::validate_autoyast_profile -> lib/autoyast.pm:301 called autoyast::init_autoyast_profile -> lib/autoyast.pm:243 called testapi::script_output
[2024-05-28T08:33:14.669136Z] [debug] [pid:2759] <<< testapi::send_key(key="ctrl-d", wait_screen_change=0)
[2024-05-28T08:33:15.004246Z] [debug] [pid:2759] tests/autoyast/verify_cloned_profile.pm:18 called autoyast::validate_autoyast_profile -> lib/autoyast.pm:301 called autoyast::init_autoyast_profile -> lib/autoyast.pm:243 called testapi::script_output
[2024-05-28T08:33:15.004601Z] [debug] [pid:2759] <<< testapi::type_string(string="(echo sx~9G; bash -eox pipefail /tmp/scriptsx~9G.sh ; echo SCRIPT_FINISHEDsx~9G-\$?-) | tee /dev/ttyS0\n", max_interval=250, wait_screen_change=0, wait_still_screen=0, timeout=30, similarity_level=47)
[2024-05-28T08:33:18.913476Z] [debug] [pid:2759] tests/autoyast/verify_cloned_profile.pm:18 called autoyast::validate_autoyast_profile -> lib/autoyast.pm:301 called autoyast::init_autoyast_profile -> lib/autoyast.pm:243 called testapi::script_output
[2024-05-28T08:33:18.913693Z] [debug] [pid:2759] <<< testapi::wait_serial(no_regex=0, regexp="SCRIPT_FINISHEDsx~9G-\\d+-", quiet=undef, expect_not_found=0, record_output=1, buffer_size=undef, timeout=90)
[32m[2024-05-28T08:33:22.970799Z] [debug] [pid:2759] >>> testapi::wait_serial: SCRIPT_FINISHEDsx~9G-\d+-: ok[0m
[2024-05-28T08:33:22.980481Z] [debug] [pid:2759] tests/autoyast/verify_cloned_profile.pm:18 called autoyast::validate_autoyast_profile -> lib/autoyast.pm:306 called testapi::record_info
[2024-05-28T08:33:22.981102Z] [debug] [pid:2759] <<< testapi::record_info(title="Summary", output="Errors found:\nnone\n\nExpressions executed:\n/ns:profile/ns:partitioning/ns:drive[ns:device[text()='/dev/vda'] and ns:disklabel[text()='gpt'] and ns:partitions[count(ns:partition)=3] and ns:type[text()='CT_DISK']]\n/ns:profile/ns:partitioning/ns:drive[ns:device[text()='/dev/vda'] and ns:disklabel[text()='gpt'] and ns:partitions[count(ns:partition)=3] and ns:type[text()='CT_DISK']]/ns:partitions/ns:partition[ns:filesystem[text()='swap'] and ns:mount[text()='swap']]\n/ns:profile/ns:partitioning/ns:drive[ns:device[text()='/dev/vdb'] and ns:disklabel[text()='gpt'] and ns:partitions[count(ns:partition)=1] and ns:type[text()='CT_DISK']]\n/ns:profile/ns:partitioning/ns:drive[ns:device[text()='/dev/vdb'] and ns:disklabel[text()='gpt'] and ns:partitions[count(ns:partition)=1] and ns:type[text()='CT_DISK']]/ns:partitions/ns:partition/ns:partition_nr[text()='1']\n/ns:profile/ns:partitioning/ns:drive[ns:device[text()='/dev/vdc'] and ns:disklabel[text()='none'] and ns:partitions[count(ns:partition)=1] and ns:type[text()='CT_DISK']]\n/ns:profile/ns:partitioning/ns:drive[ns:device[text()='/dev/vdc'] and ns:disklabel[text()='none'] and ns:partitions[count(ns:partition)=1] and ns:type[text()='CT_DISK']]/ns:partitions/ns:partition/ns:create[text()='false']\n/ns:profile/ns:partitioning/ns:drive[ns:device[text()='/dev/vdd'] and ns:disklabel[text()='gpt'] and ns:partitions[count(ns:partition)=1] and ns:type[text()='CT_DISK']]\n/ns:profile/ns:partitioning/ns:drive[ns:device[text()='/dev/vdd'] and ns:disklabel[text()='gpt'] and ns:partitions[count(ns:partition)=1] and ns:type[text()='CT_DISK']]/ns:partitions/ns:partition/ns:crypt_method[text()='luks1']\n/ns:profile/ns:partitioning/ns:drive[ns:disklabel[text()='none'] and ns:enable_snapshots[text()='false'] and .//ns:label[text()='root_multi_btrfs'] and ns:type[text()='CT_BTRFS']]\n/ns:profile/ns:partitioning/ns:drive[ns:disklabel[text()='none'] and ns:enable_snapshots[text()='false'] and .//ns:label[text()='root_multi_btrfs'] and ns:type[text()='CT_BTRFS']]/ns:btrfs_options/ns:data_raid_level[text()='raid0']\n/ns:profile/ns:partitioning/ns:drive[ns:disklabel[text()='none'] and ns:enable_snapshots[text()='false'] and .//ns:label[text()='root_multi_btrfs'] and ns:type[text()='CT_BTRFS']]/ns:btrfs_options/ns:metadata_raid_level[text()='raid1']\n/ns:profile/ns:partitioning/ns:drive[ns:disklabel[text()='none'] and ns:enable_snapshots[text()='false'] and .//ns:label[text()='root_multi_btrfs'] and ns:type[text()='CT_BTRFS']]/ns:partitions/ns:partition[ns:filesystem[text()='btrfs'] and ns:label[text()='root_multi_btrfs'] and ns:mount[text()='/'] and ns:subvolumes_prefix[text()='\@']]\n/ns:profile/ns:partitioning/ns:drive[ns:disklabel[text()='none'] and ns:enable_snapshots[text()='false'] and .//ns:label[text()='root_multi_btrfs'] and ns:type[text()='CT_BTRFS']]/ns:partitions/ns:partition[ns:filesystem[text()='btrfs'] and ns:label[text()='root_multi_btrfs'] and ns:mount[text()='/'] and ns:subvolumes_prefix[text()='\@']]/ns:subvolumes/ns:subvolume[ns:copy_on_write[text()='true'] and ns:path[text()='tmp']]\n/ns:profile/ns:partitioning/ns:drive[ns:disklabel[text()='none'] and ns:enable_snapshots[text()='false'] and .//ns:label[text()='root_multi_btrfs'] and ns:type[text()='CT_BTRFS']]/ns:partitions/ns:partition[ns:filesystem[text()='btrfs'] and ns:label[text()='root_multi_btrfs'] and ns:mount[text()='/'] and ns:subvolumes_prefix[text()='\@']]/ns:subvolumes/ns:subvolume[ns:copy_on_write[text()='true'] and ns:path[text()='usr/local']]\n/ns:profile/ns:partitioning/ns:drive[ns:disklabel[text()='none'] and ns:enable_snapshots[text()='false'] and .//ns:label[text()='root_multi_btrfs'] and ns:type[text()='CT_BTRFS']]/ns:partitions/ns:partition[ns:filesystem[text()='btrfs'] and ns:label[text()='root_multi_btrfs'] and ns:mount[text()='/'] and ns:subvolumes_prefix[text()='\@']]/ns:subvolumes/ns:subvolume[ns:copy_on_write[text()='true'] and ns:path[text()='home']]\n/ns:profile/ns:partitioning/ns:drive[ns:disklabel[text()='none'] and ns:enable_snapshots[text()='false'] and .//ns:label[text()='root_multi_btrfs'] and ns:type[text()='CT_BTRFS']]/ns:partitions/ns:partition[ns:filesystem[text()='btrfs'] and ns:label[text()='root_multi_btrfs'] and ns:mount[text()='/'] and ns:subvolumes_prefix[text()='\@']]/ns:subvolumes/ns:subvolume[ns:copy_on_write[text()='true'] and ns:path[text()='root']]\n/ns:profile/ns:partitioning/ns:drive[ns:disklabel[text()='none'] and ns:enable_snapshots[text()='false'] and .//ns:label[text()='root_multi_btrfs'] and ns:type[text()='CT_BTRFS']]/ns:partitions/ns:partition[ns:filesystem[text()='btrfs'] and ns:label[text()='root_multi_btrfs'] and ns:mount[text()='/'] and ns:subvolumes_prefix[text()='\@']]/ns:subvolumes/ns:subvolume[ns:copy_on_write[text()='true'] and ns:path[text()='srv']]\n/ns:profile/ns:partitioning/ns:drive[ns:disklabel[text()='none'] and ns:enable_snapshots[text()='false'] and .//ns:label[text()='root_multi_btrfs'] and ns:type[text()='CT_BTRFS']]/ns:partitions/ns:partition[ns:filesystem[text()='btrfs'] and ns:label[text()='root_multi_btrfs'] and ns:mount[text()='/'] and ns:subvolumes_prefix[text()='\@']]/ns:subvolumes/ns:subvolume[ns:copy_on_write[text()='false'] and ns:path[text()='var']]\n/ns:profile/ns:partitioning/ns:drive[ns:disklabel[text()='none'] and ns:enable_snapshots[text()='false'] and .//ns:label[text()='root_multi_btrfs'] and ns:type[text()='CT_BTRFS']]/ns:partitions/ns:partition[ns:filesystem[text()='btrfs'] and ns:label[text()='root_multi_btrfs'] and ns:mount[text()='/'] and ns:subvolumes_prefix[text()='\@']]/ns:subvolumes/ns:subvolume[ns:copy_on_write[text()='true'] and ns:path[text()='opt']]\n/ns:profile/ns:partitioning/ns:drive[ns:disklabel[text()='none'] and .//ns:label[text()='test_multi_btrfs'] and ns:type[text()='CT_BTRFS']]\n/ns:profile/ns:partitioning/ns:drive[ns:disklabel[text()='none'] and .//ns:label[text()='test_multi_btrfs'] and ns:type[text()='CT_BTRFS']]/ns:btrfs_options/ns:data_raid_level[text()='raid0']\n/ns:profile/ns:partitioning/ns:drive[ns:disklabel[text()='none'] and .//ns:label[text()='test_multi_btrfs'] and ns:type[text()='CT_BTRFS']]/ns:btrfs_options/ns:metadata_raid_level[text()='raid1']\n/ns:profile/ns:partitioning/ns:drive[ns:disklabel[text()='none'] and .//ns:label[text()='test_multi_btrfs'] and ns:type[text()='CT_BTRFS']]/ns:partitions/ns:partition[ns:filesystem[text()='btrfs'] and ns:label[text()='test_multi_btrfs'] and ns:mount[text()='/test'] and ns:subvolumes_prefix[not(text())]]\n", result="ok")
[1;34m[2024-05-28T08:33:23.008498Z] [debug] [pid:2759] ||| finished verify_cloned_profile autoyast (runtime: 18 s)[0m
[37m[2024-05-28T08:33:23.010553Z] [debug] [pid:2742] stopping autotest process 2759[0m
[37m[2024-05-28T08:33:23.025963Z] [debug] [pid:2742] [autotest] process exited: 0[0m
[37m[2024-05-28T08:33:23.126243Z] [debug] [pid:2742] done with autotest process[0m
[37m[2024-05-28T08:33:23.126567Z] [debug] [pid:2742] stopping command server 2752 because test execution ended[0m
[37m[2024-05-28T08:33:23.126647Z] [debug] [pid:2742] isotovideo: informing websocket clients before stopping command server: http://127.0.0.1:20303/BNGyhHHiGaVcXGrV/broadcast[0m
[37m[2024-05-28T08:33:23.141518Z] [debug] [pid:2742] commands process exited: 0[0m
[37m[2024-05-28T08:33:23.241865Z] [debug] [pid:2742] done with command server[0m
[37m[2024-05-28T08:33:23.241942Z] [debug] [pid:2742] isotovideo done[0m
[37m[2024-05-28T08:33:23.242547Z] [debug] [pid:3081] QEMU status is not 'shutdown', it is 'running'[0m
[37m[2024-05-28T08:33:23.242684Z] [debug] [pid:2742] backend shutdown state: [0m
[33m[2024-05-28T08:33:23.242995Z] [info] [pid:3081] ::: OpenQA::Qemu::Proc::save_state: Saving QEMU state to qemu_state.json[0m
[37m[2024-05-28T08:33:24.298212Z] [debug] [pid:3081] Passing remaining frames to the video encoder[0m
frame= 1016 fps=0.8 q=0.0 Lsize=     875kB time=00:00:42.29 bitrate= 169.4kbits/s speed=0.0343x    
video:867kB audio:0kB subtitle:0kB other streams:0kB global headers:0kB muxing overhead: 0.854455%
[37m[2024-05-28T08:33:25.166072Z] [debug] [pid:3081] Waiting for video encoder to finalize the video[0m
[37m[2024-05-28T08:33:25.166156Z] [debug] [pid:3081] The built-in video encoder (pid 3283) terminated[0m
[37m[2024-05-28T08:33:25.166210Z] [debug] [pid:3081] The external video encoder (pid 3282) terminated[0m
[37m[2024-05-28T08:33:25.166740Z] [debug] [pid:3081] QEMU: qemu-system-x86_64: terminating on signal 15 from pid 3081 (/usr/bin/isotovideo: backen)[0m
[37m[2024-05-28T08:33:25.167287Z] [debug] [pid:3081] sending magic and exit[0m
[37m[2024-05-28T08:33:25.167554Z] [debug] [pid:2742] received magic close[0m
[37m[2024-05-28T08:33:25.230462Z] [debug] [pid:2742] backend process exited: 0[0m
Use of uninitialized value $name in pattern match (m//) at /usr/lib/os-autoinst/OpenQA/Isotovideo/Utils.pm line 332.
	OpenQA::Isotovideo::Utils::handle_generated_assets(OpenQA::Isotovideo::CommandHandler=HASH(0x561fdcc721b0), "") called at /usr/bin/isotovideo line 204
	eval {...} called at /usr/bin/isotovideo line 161
Use of uninitialized value $name in pattern match (m//) at /usr/lib/os-autoinst/OpenQA/Isotovideo/Utils.pm line 332.
	OpenQA::Isotovideo::Utils::handle_generated_assets(OpenQA::Isotovideo::CommandHandler=HASH(0x561fdcc721b0), "") called at /usr/bin/isotovideo line 204
	eval {...} called at /usr/bin/isotovideo line 161
Use of uninitialized value $name in pattern match (m//) at /usr/lib/os-autoinst/OpenQA/Isotovideo/Utils.pm line 332.
	OpenQA::Isotovideo::Utils::handle_generated_assets(OpenQA::Isotovideo::CommandHandler=HASH(0x561fdcc721b0), "") called at /usr/bin/isotovideo line 204
	eval {...} called at /usr/bin/isotovideo line 161
Use of uninitialized value $name in pattern match (m//) at /usr/lib/os-autoinst/OpenQA/Isotovideo/Utils.pm line 332.
	OpenQA::Isotovideo::Utils::handle_generated_assets(OpenQA::Isotovideo::CommandHandler=HASH(0x561fdcc721b0), "") called at /usr/bin/isotovideo line 204
	eval {...} called at /usr/bin/isotovideo line 161
[37m[2024-05-28T08:33:25.331986Z] [debug] [pid:2742] stopping backend process 3081[0m
[37m[2024-05-28T08:33:25.332081Z] [debug] [pid:2742] done with backend process[0m
2742: EXIT 0
[2024-05-28T08:33:25.381198Z] [info] Isotovideo exit status: 0
[2024-05-28T08:33:25.419679Z] [info] +++ worker notes +++
[2024-05-28T08:33:25.419793Z] [info] End time: 2024-05-28 08:33:25
[2024-05-28T08:33:25.419865Z] [info] Result: done
[2024-05-28T08:33:25.423259Z] [info] Uploading autoyast_multi_btrfs.xml
[2024-05-28T08:33:25.469229Z] [info] Uploading clone-autoinst.xml
[2024-05-28T08:33:25.495557Z] [info] Uploading clone-installedSystem.xml
[2024-05-28T08:33:25.529510Z] [info] Uploading clone-y2logs_clone.tar.bz2
[2024-05-28T08:33:25.651710Z] [info] Uploading video.webm
[2024-05-28T08:33:25.736193Z] [info] Uploading autoinst-log.txt
